From 3ae035bd98b8b56e777f6a5fb73a964b68fbbc42 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 17:04:22 -0700 Subject: [PATCH 01/18] Implement a server tracing subscriber with a log layer --- Cargo.lock | 2 +- crates/ruff/Cargo.toml | 1 - crates/ruff/src/commands/server.rs | 65 +-------------- crates/ruff/src/lib.rs | 6 +- crates/ruff_server/Cargo.toml | 1 + crates/ruff_server/src/lib.rs | 6 +- crates/ruff_server/src/server.rs | 7 ++ crates/ruff_server/src/trace.rs | 127 +++++++++++++++++++++++++++++ 8 files changed, 144 insertions(+), 71 deletions(-) create mode 100644 crates/ruff_server/src/trace.rs diff --git a/Cargo.lock b/Cargo.lock index 0654eab5f9960..3d92bd3fdee58 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1943,7 +1943,6 @@ dependencies = [ "toml", "tracing", "tracing-subscriber", - "tracing-tree", "walkdir", "wild", ] @@ -2344,6 +2343,7 @@ dependencies = [ "serde_json", "shellexpand", "tracing", + "tracing-subscriber", "walkdir", ] diff --git a/crates/ruff/Cargo.toml b/crates/ruff/Cargo.toml index e069a649a8b0a..0a9d6cea6332f 100644 --- a/crates/ruff/Cargo.toml +++ b/crates/ruff/Cargo.toml @@ -54,7 +54,6 @@ thiserror = { workspace = true } toml = { workspace = true } tracing = { workspace = true, features = ["log"] } tracing-subscriber = { workspace = true, features = ["registry"] } -tracing-tree = { workspace = true } walkdir = { workspace = true } wild = { workspace = true } diff --git a/crates/ruff/src/commands/server.rs b/crates/ruff/src/commands/server.rs index bb7b3efe908b7..d35b2c1ce46f6 100644 --- a/crates/ruff/src/commands/server.rs +++ b/crates/ruff/src/commands/server.rs @@ -2,78 +2,15 @@ use std::num::NonZeroUsize; use crate::ExitStatus; use anyhow::Result; -use ruff_linter::logging::LogLevel; use ruff_server::Server; -use tracing::{level_filters::LevelFilter, metadata::Level, subscriber::Interest, Metadata}; -use tracing_subscriber::{ - layer::{Context, Filter, SubscriberExt}, - Layer, Registry, -}; -use tracing_tree::time::Uptime; -pub(crate) fn run_server( - preview: bool, - worker_threads: NonZeroUsize, - log_level: LogLevel, -) -> Result { +pub(crate) fn run_server(preview: bool, worker_threads: NonZeroUsize) -> Result { if !preview { tracing::error!("--preview needs to be provided as a command line argument while the server is still unstable.\nFor example: `ruff server --preview`"); return Ok(ExitStatus::Error); } - let trace_level = if log_level == LogLevel::Verbose { - Level::TRACE - } else { - Level::DEBUG - }; - - let subscriber = Registry::default().with( - tracing_tree::HierarchicalLayer::default() - .with_indent_lines(true) - .with_indent_amount(2) - .with_bracketed_fields(true) - .with_targets(true) - .with_writer(|| Box::new(std::io::stderr())) - .with_timer(Uptime::default()) - .with_filter(LoggingFilter { trace_level }), - ); - - tracing::subscriber::set_global_default(subscriber)?; let server = Server::new(worker_threads)?; server.run().map(|()| ExitStatus::Success) } - -struct LoggingFilter { - trace_level: Level, -} - -impl LoggingFilter { - fn is_enabled(&self, meta: &Metadata<'_>) -> bool { - let filter = if meta.target().starts_with("ruff") { - self.trace_level - } else { - Level::INFO - }; - - meta.level() <= &filter - } -} - -impl Filter for LoggingFilter { - fn enabled(&self, meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool { - self.is_enabled(meta) - } - - fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { - if self.is_enabled(meta) { - Interest::always() - } else { - Interest::never() - } - } - - fn max_level_hint(&self) -> Option { - Some(LevelFilter::from_level(self.trace_level)) - } -} diff --git a/crates/ruff/src/lib.rs b/crates/ruff/src/lib.rs index e61a9ec441b26..7281a3be87266 100644 --- a/crates/ruff/src/lib.rs +++ b/crates/ruff/src/lib.rs @@ -201,7 +201,7 @@ pub fn run( } Command::Check(args) => check(args, global_options), Command::Format(args) => format(args, global_options), - Command::Server(args) => server(args, global_options.log_level()), + Command::Server(args) => server(args), } } @@ -215,7 +215,7 @@ fn format(args: FormatCommand, global_options: GlobalConfigArgs) -> Result Result { +fn server(args: ServerCommand) -> Result { let ServerCommand { preview } = args; let four = NonZeroUsize::new(4).unwrap(); @@ -224,7 +224,7 @@ fn server(args: ServerCommand, log_level: LogLevel) -> Result { let worker_threads = std::thread::available_parallelism() .unwrap_or(four) .max(four); - commands::server::run_server(preview, worker_threads, log_level) + commands::server::run_server(preview, worker_threads) } pub fn check(args: CheckCommand, global_options: GlobalConfigArgs) -> Result { diff --git a/crates/ruff_server/Cargo.toml b/crates/ruff_server/Cargo.toml index 64e48b07ef0fb..2da3aff1c05d1 100644 --- a/crates/ruff_server/Cargo.toml +++ b/crates/ruff_server/Cargo.toml @@ -38,6 +38,7 @@ serde = { workspace = true } serde_json = { workspace = true } shellexpand = { workspace = true } tracing = { workspace = true } +tracing-subscriber = { workspace = true } walkdir = { workspace = true } [dev-dependencies] diff --git a/crates/ruff_server/src/lib.rs b/crates/ruff_server/src/lib.rs index 579ab3e159dce..e94a8df72ddc1 100644 --- a/crates/ruff_server/src/lib.rs +++ b/crates/ruff_server/src/lib.rs @@ -4,14 +4,16 @@ pub use edit::{PositionEncoding, TextDocument}; use lsp_types::CodeActionKind; pub use server::Server; +#[macro_use] +mod message; + mod edit; mod fix; mod format; mod lint; -#[macro_use] -mod message; mod server; mod session; +mod trace; pub(crate) const SERVER_NAME: &str = "ruff"; pub(crate) const DIAGNOSTIC_NAME: &str = "Ruff"; diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index 76c5f1a55f6c2..815377782fc21 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -41,6 +41,7 @@ pub(crate) type Result = std::result::Result; pub struct Server { connection: Connection, + tracing_guard: tracing::subscriber::DefaultGuard, client_capabilities: ClientCapabilities, worker_threads: NonZeroUsize, session: Session, @@ -63,6 +64,9 @@ impl Server { crate::version(), )?; + // TODO(jane): Support a log level setting + let log_level = crate::trace::LogLevel::Info; + let tracing_guard = crate::trace::init_tracing(connection.make_sender(), log_level); crate::message::init_messenger(connection.make_sender()); let AllSettings { @@ -102,6 +106,7 @@ impl Server { Ok(Self { connection, + tracing_guard, worker_threads, session: Session::new( &client_capabilities, @@ -121,7 +126,9 @@ impl Server { self.session, self.worker_threads, )?; + std::mem::drop(self.tracing_guard); self.connection.close()?; + tracing::info!("Client connection has been closed"); Ok(()) })? .join() diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs new file mode 100644 index 0000000000000..385516436dd5b --- /dev/null +++ b/crates/ruff_server/src/trace.rs @@ -0,0 +1,127 @@ +use lsp_types::notification::Notification; +use serde::Deserialize; +use std::sync::OnceLock; +use tracing::{level_filters::LevelFilter, Event}; +use tracing_subscriber::layer::SubscriberExt; + +use crate::server::ClientSender; + +static LOGGING_SENDER: OnceLock = OnceLock::new(); + +pub(crate) fn init_tracing( + sender: ClientSender, + filter: LogLevel, +) -> tracing::subscriber::DefaultGuard { + LOGGING_SENDER + .set(sender) + .expect("logging sender should only be initialized once"); + + let subscriber = tracing_subscriber::Registry::default().with(LogLayer { filter }); + + tracing::subscriber::set_default(subscriber) +} + +#[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)] +#[serde(rename_all = "lowercase")] +pub(crate) enum LogLevel { + #[default] + Error, + Warn, + Info, + Debug, +} + +impl LogLevel { + fn from_trace_level(level: tracing::Level) -> Self { + match level { + tracing::Level::ERROR => Self::Error, + tracing::Level::WARN => Self::Warn, + tracing::Level::INFO => Self::Info, + _ => Self::Debug, + } + } + + fn message_type(self) -> lsp_types::MessageType { + match self { + Self::Error => lsp_types::MessageType::ERROR, + Self::Warn => lsp_types::MessageType::WARNING, + Self::Info => lsp_types::MessageType::INFO, + // TODO(jane): LSP `0.3.18` will introduce `MessageType::DEBUG`, + // and we should consider using that. + Self::Debug => lsp_types::MessageType::LOG, + } + } + + fn trace_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, + } + } +} + +struct LogLayer { + filter: LogLevel, +} + +impl tracing_subscriber::Layer for LogLayer { + fn register_callsite( + &self, + metadata: &'static tracing::Metadata<'static>, + ) -> tracing::subscriber::Interest { + if metadata.is_event() + && metadata + .fields() + .iter() + .any(|field| field.name() == "message") + { + tracing::subscriber::Interest::always() + } else { + tracing::subscriber::Interest::never() + } + } + + fn max_level_hint(&self) -> Option { + Some(LevelFilter::from_level(self.filter.trace_level())) + } + + fn on_event( + &self, + event: &Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, tracing_subscriber::Registry>, + ) { + let mut message_visitor = + LogMessageVisitor(LogLevel::from_trace_level(*event.metadata().level())); + event.record(&mut message_visitor); + } +} + +#[derive(Default)] +struct LogMessageVisitor(LogLevel); + +impl tracing::field::Visit for LogMessageVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() == "message" { + log(format!("{value:?}"), self.0); + } + } +} + +#[inline] +fn log(message: String, level: LogLevel) { + let _ = LOGGING_SENDER + .get() + .expect("logging channel should be initialized") + .send(lsp_server::Message::Notification( + lsp_server::Notification { + method: lsp_types::notification::LogMessage::METHOD.into(), + params: serde_json::to_value(lsp_types::LogMessageParams { + typ: level.message_type(), + message, + }) + .expect("log notification should serialize"), + }, + )); +} From 511a19ba411449b0907f54166dbeabc7cff678c5 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 17:55:33 -0700 Subject: [PATCH 02/18] Use client-provided trace value --- crates/ruff_server/src/server.rs | 8 +- crates/ruff_server/src/server/api.rs | 3 + .../src/server/api/notifications.rs | 2 + .../src/server/api/notifications/set_trace.rs | 23 +++++ crates/ruff_server/src/trace.rs | 87 +++++++++++++------ 5 files changed, 93 insertions(+), 30 deletions(-) create mode 100644 crates/ruff_server/src/server/api/notifications/set_trace.rs diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index 815377782fc21..4055c69e05873 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -64,9 +64,11 @@ impl Server { crate::version(), )?; - // TODO(jane): Support a log level setting - let log_level = crate::trace::LogLevel::Info; - let tracing_guard = crate::trace::init_tracing(connection.make_sender(), log_level); + if let Some(trace) = init_params.trace { + crate::trace::set_trace_value(trace); + } + + let tracing_guard = crate::trace::init_tracing(connection.make_sender()); crate::message::init_messenger(connection.make_sender()); let AllSettings { diff --git a/crates/ruff_server/src/server/api.rs b/crates/ruff_server/src/server/api.rs index 6917d0ff6c387..459ae8fe8f645 100644 --- a/crates/ruff_server/src/server/api.rs +++ b/crates/ruff_server/src/server/api.rs @@ -93,6 +93,9 @@ pub(super) fn notification<'a>(notif: server::Notification) -> Task<'a> { notification::DidCloseNotebook::METHOD => { local_notification_task::(notif) } + notification::SetTrace::METHOD => { + local_notification_task::(notif) + } method => { tracing::warn!("Received notification {method} which does not have a handler."); return Task::nothing(); diff --git a/crates/ruff_server/src/server/api/notifications.rs b/crates/ruff_server/src/server/api/notifications.rs index ade0c2fbd510f..feb7771c22408 100644 --- a/crates/ruff_server/src/server/api/notifications.rs +++ b/crates/ruff_server/src/server/api/notifications.rs @@ -8,6 +8,7 @@ mod did_close; mod did_close_notebook; mod did_open; mod did_open_notebook; +mod set_trace; use super::traits::{NotificationHandler, SyncNotificationHandler}; pub(super) use cancel::Cancel; @@ -20,3 +21,4 @@ pub(super) use did_close::DidClose; pub(super) use did_close_notebook::DidCloseNotebook; pub(super) use did_open::DidOpen; pub(super) use did_open_notebook::DidOpenNotebook; +pub(super) use set_trace::SetTrace; diff --git a/crates/ruff_server/src/server/api/notifications/set_trace.rs b/crates/ruff_server/src/server/api/notifications/set_trace.rs new file mode 100644 index 0000000000000..9223d9e42b237 --- /dev/null +++ b/crates/ruff_server/src/server/api/notifications/set_trace.rs @@ -0,0 +1,23 @@ +use crate::server::client::{Notifier, Requester}; +use crate::server::Result; +use crate::session::Session; +use lsp_types as types; +use lsp_types::notification as notif; + +pub(crate) struct SetTrace; + +impl super::NotificationHandler for SetTrace { + type NotificationType = notif::SetTrace; +} + +impl super::SyncNotificationHandler for SetTrace { + fn run( + _session: &mut Session, + _notifier: Notifier, + _requester: &mut Requester, + params: types::SetTraceParams, + ) -> Result<()> { + crate::trace::set_trace_value(params.value); + Ok(()) + } +} diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index 385516436dd5b..bb31ce7457e4a 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -1,22 +1,29 @@ -use lsp_types::notification::Notification; +use lsp_types::{notification::Notification, TraceValue}; use serde::Deserialize; -use std::sync::OnceLock; +use std::sync::{Mutex, OnceLock}; use tracing::{level_filters::LevelFilter, Event}; -use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::{layer::SubscriberExt, Layer}; use crate::server::ClientSender; static LOGGING_SENDER: OnceLock = OnceLock::new(); -pub(crate) fn init_tracing( - sender: ClientSender, - filter: LogLevel, -) -> tracing::subscriber::DefaultGuard { +static TRACE_VALUE: Mutex = Mutex::new(lsp_types::TraceValue::Messages); + +pub(crate) fn set_trace_value(trace_value: TraceValue) { + let mut global_trace_value = TRACE_VALUE + .lock() + .expect("trace value mutex should be available"); + *global_trace_value = trace_value; +} + +pub(crate) fn init_tracing(sender: ClientSender) -> tracing::subscriber::DefaultGuard { LOGGING_SENDER .set(sender) .expect("logging sender should only be initialized once"); - let subscriber = tracing_subscriber::Registry::default().with(LogLayer { filter }); + let subscriber = + tracing_subscriber::Registry::default().with(LogLayer.with_filter(TraceValueFilter)); tracing::subscriber::set_default(subscriber) } @@ -51,42 +58,61 @@ impl LogLevel { Self::Debug => lsp_types::MessageType::LOG, } } +} - fn trace_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, +struct LogLayer; + +struct TraceValueFilter; + +impl TraceValueFilter { + fn ruff_tracing_level() -> tracing::Level { + match trace_value() { + lsp_types::TraceValue::Verbose => tracing::Level::TRACE, + lsp_types::TraceValue::Messages => tracing::Level::INFO, + lsp_types::TraceValue::Off => tracing::Level::ERROR, + } + } + + fn default_tracing_level() -> tracing::Level { + match trace_value() { + lsp_types::TraceValue::Off => tracing::Level::ERROR, + _ => tracing::Level::INFO, } } } -struct LogLayer { - filter: LogLevel, +impl tracing_subscriber::layer::Filter for TraceValueFilter { + fn enabled( + &self, + meta: &tracing::Metadata<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + let filter = if meta.target().starts_with("ruff") { + Self::ruff_tracing_level() + } else { + Self::default_tracing_level() + }; + + meta.level() <= &filter + } + + fn max_level_hint(&self) -> Option { + Some(LevelFilter::from_level(Self::ruff_tracing_level())) + } } impl tracing_subscriber::Layer for LogLayer { fn register_callsite( &self, - metadata: &'static tracing::Metadata<'static>, + meta: &'static tracing::Metadata<'static>, ) -> tracing::subscriber::Interest { - if metadata.is_event() - && metadata - .fields() - .iter() - .any(|field| field.name() == "message") - { + if meta.is_event() && meta.fields().iter().any(|field| field.name() == "message") { tracing::subscriber::Interest::always() } else { tracing::subscriber::Interest::never() } } - fn max_level_hint(&self) -> Option { - Some(LevelFilter::from_level(self.filter.trace_level())) - } - fn on_event( &self, event: &Event<'_>, @@ -125,3 +151,10 @@ fn log(message: String, level: LogLevel) { }, )); } + +#[inline] +fn trace_value() -> TraceValue { + *TRACE_VALUE + .lock() + .expect("trace value mutex should be available") +} From 5fd4739c8f542723dea221ccd1be70e199dfc16a Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 19:32:40 -0700 Subject: [PATCH 03/18] Remove trace value filter in favor of a log level filter --- crates/ruff_server/src/message.rs | 5 ++- crates/ruff_server/src/server.rs | 6 +--- crates/ruff_server/src/trace.rs | 53 +++++++++++++------------------ 3 files changed, 27 insertions(+), 37 deletions(-) diff --git a/crates/ruff_server/src/message.rs b/crates/ruff_server/src/message.rs index bd759feb1142e..2807ce8b7baa4 100644 --- a/crates/ruff_server/src/message.rs +++ b/crates/ruff_server/src/message.rs @@ -32,7 +32,10 @@ pub(crate) fn init_messenger(client_sender: ClientSender) { } let backtrace = std::backtrace::Backtrace::force_capture(); - tracing::error!("{panic_info}\n{backtrace}"); + #[allow(clippy::print_stderr)] + { + eprintln!("{panic_info}\n{backtrace}"); + } })); } diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index 4055c69e05873..59e2807e9fff1 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -41,7 +41,6 @@ pub(crate) type Result = std::result::Result; pub struct Server { connection: Connection, - tracing_guard: tracing::subscriber::DefaultGuard, client_capabilities: ClientCapabilities, worker_threads: NonZeroUsize, session: Session, @@ -68,8 +67,8 @@ impl Server { crate::trace::set_trace_value(trace); } - let tracing_guard = crate::trace::init_tracing(connection.make_sender()); crate::message::init_messenger(connection.make_sender()); + crate::trace::init_tracing(connection.make_sender()); let AllSettings { global_settings, @@ -108,7 +107,6 @@ impl Server { Ok(Self { connection, - tracing_guard, worker_threads, session: Session::new( &client_capabilities, @@ -128,9 +126,7 @@ impl Server { self.session, self.worker_threads, )?; - std::mem::drop(self.tracing_guard); self.connection.close()?; - tracing::info!("Client connection has been closed"); Ok(()) })? .join() diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index bb31ce7457e4a..55afeee50d047 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -17,15 +17,19 @@ pub(crate) fn set_trace_value(trace_value: TraceValue) { *global_trace_value = trace_value; } -pub(crate) fn init_tracing(sender: ClientSender) -> tracing::subscriber::DefaultGuard { +pub(crate) fn init_tracing(sender: ClientSender) { LOGGING_SENDER .set(sender) .expect("logging sender should only be initialized once"); + // TODO(jane): Provide a way to set the log level let subscriber = - tracing_subscriber::Registry::default().with(LogLayer.with_filter(TraceValueFilter)); + tracing_subscriber::Registry::default().with(LogLayer.with_filter(LogFilter { + filter: LogLevel::Info, + })); - tracing::subscriber::set_default(subscriber) + 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)] @@ -58,46 +62,40 @@ impl LogLevel { Self::Debug => lsp_types::MessageType::LOG, } } -} - -struct LogLayer; - -struct TraceValueFilter; -impl TraceValueFilter { - fn ruff_tracing_level() -> tracing::Level { - match trace_value() { - lsp_types::TraceValue::Verbose => tracing::Level::TRACE, - lsp_types::TraceValue::Messages => tracing::Level::INFO, - lsp_types::TraceValue::Off => tracing::Level::ERROR, + fn trace_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, } } +} - fn default_tracing_level() -> tracing::Level { - match trace_value() { - lsp_types::TraceValue::Off => tracing::Level::ERROR, - _ => tracing::Level::INFO, - } - } +struct LogLayer; + +struct LogFilter { + filter: LogLevel, } -impl tracing_subscriber::layer::Filter for TraceValueFilter { +impl tracing_subscriber::layer::Filter for LogFilter { fn enabled( &self, meta: &tracing::Metadata<'_>, _: &tracing_subscriber::layer::Context<'_, S>, ) -> bool { let filter = if meta.target().starts_with("ruff") { - Self::ruff_tracing_level() + self.filter.trace_level() } else { - Self::default_tracing_level() + tracing::Level::INFO }; meta.level() <= &filter } fn max_level_hint(&self) -> Option { - Some(LevelFilter::from_level(Self::ruff_tracing_level())) + Some(LevelFilter::from_level(self.filter.trace_level())) } } @@ -151,10 +149,3 @@ fn log(message: String, level: LogLevel) { }, )); } - -#[inline] -fn trace_value() -> TraceValue { - *TRACE_VALUE - .lock() - .expect("trace value mutex should be available") -} From d2986ba874214d91114d55e810b1a800a7b4ad1d Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 19:33:15 -0700 Subject: [PATCH 04/18] Use Off as a default trace value --- crates/ruff_server/src/trace.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index 55afeee50d047..c715e24a8080e 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -8,7 +8,7 @@ use crate::server::ClientSender; static LOGGING_SENDER: OnceLock = OnceLock::new(); -static TRACE_VALUE: Mutex = Mutex::new(lsp_types::TraceValue::Messages); +static TRACE_VALUE: Mutex = Mutex::new(lsp_types::TraceValue::Off); pub(crate) fn set_trace_value(trace_value: TraceValue) { let mut global_trace_value = TRACE_VALUE From 4a4197eb71b7c13992b1a3bc02345f9058fb1cb1 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 19:45:42 -0700 Subject: [PATCH 05/18] Write to stderr during connection shutdown --- crates/ruff_server/src/server/connection.rs | 16 +++++++++++----- crates/ruff_server/src/trace.rs | 5 +++++ 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/crates/ruff_server/src/server/connection.rs b/crates/ruff_server/src/server/connection.rs index c04567c57ae84..414c131c60ccd 100644 --- a/crates/ruff_server/src/server/connection.rs +++ b/crates/ruff_server/src/server/connection.rs @@ -88,21 +88,27 @@ impl Connection { lsp::Message::Request(lsp::Request { id, method, .. }) if method == lsp_types::request::Shutdown::METHOD => { - self.sender - .send(lsp::Response::new_ok(id.clone(), ()).into())?; - tracing::info!("Shutdown request received. Waiting for an exit notification..."); - match self.receiver.recv_timeout(std::time::Duration::from_secs(30))? { + tracing::subscriber::with_default(crate::trace::stderr_subscriber(), || { + self.sender + .send(lsp::Response::new_ok(id.clone(), ()).into())?; + tracing::info!( + "Shutdown request received. Waiting for an exit notification..." + ); + match self.receiver.recv_timeout(std::time::Duration::from_secs(30))? { lsp::Message::Notification(lsp::Notification { method, .. }) if method == lsp_types::notification::Exit::METHOD => { tracing::info!("Exit notification received. Server shutting down..."); Ok(true) }, message => anyhow::bail!("Server received unexpected message {message:?} while waiting for exit notification") } + }) } lsp::Message::Notification(lsp::Notification { method, .. }) if method == lsp_types::notification::Exit::METHOD => { - tracing::error!("Server received an exit notification before a shutdown request was sent. Exiting..."); + tracing::subscriber::with_default(crate::trace::stderr_subscriber(), || { + tracing::error!("Server received an exit notification before a shutdown request was sent. Exiting..."); + }); Ok(true) } _ => Ok(false), diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index c715e24a8080e..d31bb535d8041 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -10,6 +10,11 @@ static LOGGING_SENDER: OnceLock = OnceLock::new(); static TRACE_VALUE: Mutex = Mutex::new(lsp_types::TraceValue::Off); +pub(crate) fn stderr_subscriber() -> impl tracing::Subscriber { + tracing_subscriber::registry() + .with(tracing_subscriber::fmt::layer().with_writer(|| Box::new(std::io::stderr()))) +} + pub(crate) fn set_trace_value(trace_value: TraceValue) { let mut global_trace_value = TRACE_VALUE .lock() From b36308884af248ea3aaaf467b6515357728ccead Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 19:52:09 -0700 Subject: [PATCH 06/18] Revert "Write to stderr during connection shutdown" This reverts commit 4a4197eb71b7c13992b1a3bc02345f9058fb1cb1. --- crates/ruff_server/src/server/connection.rs | 16 +++++----------- crates/ruff_server/src/trace.rs | 5 ----- 2 files changed, 5 insertions(+), 16 deletions(-) diff --git a/crates/ruff_server/src/server/connection.rs b/crates/ruff_server/src/server/connection.rs index 414c131c60ccd..c04567c57ae84 100644 --- a/crates/ruff_server/src/server/connection.rs +++ b/crates/ruff_server/src/server/connection.rs @@ -88,27 +88,21 @@ impl Connection { lsp::Message::Request(lsp::Request { id, method, .. }) if method == lsp_types::request::Shutdown::METHOD => { - tracing::subscriber::with_default(crate::trace::stderr_subscriber(), || { - self.sender - .send(lsp::Response::new_ok(id.clone(), ()).into())?; - tracing::info!( - "Shutdown request received. Waiting for an exit notification..." - ); - match self.receiver.recv_timeout(std::time::Duration::from_secs(30))? { + self.sender + .send(lsp::Response::new_ok(id.clone(), ()).into())?; + tracing::info!("Shutdown request received. Waiting for an exit notification..."); + match self.receiver.recv_timeout(std::time::Duration::from_secs(30))? { lsp::Message::Notification(lsp::Notification { method, .. }) if method == lsp_types::notification::Exit::METHOD => { tracing::info!("Exit notification received. Server shutting down..."); Ok(true) }, message => anyhow::bail!("Server received unexpected message {message:?} while waiting for exit notification") } - }) } lsp::Message::Notification(lsp::Notification { method, .. }) if method == lsp_types::notification::Exit::METHOD => { - tracing::subscriber::with_default(crate::trace::stderr_subscriber(), || { - tracing::error!("Server received an exit notification before a shutdown request was sent. Exiting..."); - }); + tracing::error!("Server received an exit notification before a shutdown request was sent. Exiting..."); Ok(true) } _ => Ok(false), diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index d31bb535d8041..c715e24a8080e 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -10,11 +10,6 @@ static LOGGING_SENDER: OnceLock = OnceLock::new(); static TRACE_VALUE: Mutex = Mutex::new(lsp_types::TraceValue::Off); -pub(crate) fn stderr_subscriber() -> impl tracing::Subscriber { - tracing_subscriber::registry() - .with(tracing_subscriber::fmt::layer().with_writer(|| Box::new(std::io::stderr()))) -} - pub(crate) fn set_trace_value(trace_value: TraceValue) { let mut global_trace_value = TRACE_VALUE .lock() From 2505dce12497d67920d885b2be093c8e86527ff3 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 4 Jun 2024 19:55:20 -0700 Subject: [PATCH 07/18] Remove tracing-subscriber dependency --- Cargo.lock | 1 - crates/ruff/Cargo.toml | 1 - 2 files changed, 2 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 3d92bd3fdee58..7a69b5945f003 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1942,7 +1942,6 @@ dependencies = [ "tikv-jemallocator", "toml", "tracing", - "tracing-subscriber", "walkdir", "wild", ] diff --git a/crates/ruff/Cargo.toml b/crates/ruff/Cargo.toml index 0a9d6cea6332f..ca542b60b354f 100644 --- a/crates/ruff/Cargo.toml +++ b/crates/ruff/Cargo.toml @@ -53,7 +53,6 @@ tempfile = { workspace = true } thiserror = { workspace = true } toml = { workspace = true } tracing = { workspace = true, features = ["log"] } -tracing-subscriber = { workspace = true, features = ["registry"] } walkdir = { workspace = true } wild = { workspace = true } From f0080ef100d57c43f4e3814c52f5c666854040d1 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Wed, 5 Jun 2024 13:24:57 -0700 Subject: [PATCH 08/18] Introduce global logLevel setting --- crates/ruff_server/src/server.rs | 8 +++++++- crates/ruff_server/src/session/settings.rs | 22 +++++++++++++++++++--- crates/ruff_server/src/trace.rs | 9 +++------ 3 files changed, 29 insertions(+), 10 deletions(-) diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index 59e2807e9fff1..d5d8bf885cc1f 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -68,7 +68,6 @@ impl Server { } crate::message::init_messenger(connection.make_sender()); - crate::trace::init_tracing(connection.make_sender()); let AllSettings { global_settings, @@ -79,6 +78,13 @@ impl Server { .unwrap_or_else(|| serde_json::Value::Object(serde_json::Map::default())), ); + crate::trace::init_tracing( + connection.make_sender(), + global_settings + .log_level() + .unwrap_or(crate::trace::LogLevel::Info), + ); + let mut workspace_for_url = |url: lsp_types::Url| { let Some(workspace_settings) = workspace_settings.as_mut() else { return (url, ClientSettings::default()); diff --git a/crates/ruff_server/src/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 8fc98572bf139..6d07d9b4b0d8a 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -70,6 +70,7 @@ pub(crate) struct ClientSettings { exclude: Option>, line_length: Option, configuration_preference: Option, + pub(crate) log_level: Option, } /// This is a direct representation of the workspace settings schema, @@ -177,6 +178,15 @@ impl AllSettings { } } +impl ClientSettings { + /// Log level is taken directly from client settings, since we need it before + /// we resolve workspace settings. Additionally, this setting should only be set in global settings, + /// and any log level set in workspace settings will be ignored. + pub(crate) fn log_level(&self) -> Option { + self.log_level + } +} + impl ResolvedClientSettings { /// Resolves a series of client settings, prioritizing workspace settings over global settings. /// Any fields not specified by either are set to their defaults. @@ -424,6 +434,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, + log_level: None, }, workspace_settings: [ WorkspaceSettings { @@ -472,6 +483,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, + log_level: None, }, workspace: Url { scheme: "file", @@ -533,6 +545,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, + log_level: None, }, workspace: Url { scheme: "file", @@ -588,7 +601,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: ConfigurationPreference::default(), - } + }, } ); let path = @@ -619,7 +632,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: ConfigurationPreference::EditorFirst, - } + }, } ); } @@ -673,6 +686,9 @@ mod tests { ), ), configuration_preference: None, + log_level: Some( + Warn, + ), }, } "###); @@ -703,7 +719,7 @@ mod tests { exclude: Some(vec!["third_party".into()]), line_length: Some(LineLength::try_from(80).unwrap()), configuration_preference: ConfigurationPreference::EditorFirst, - } + }, } ); } diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index c715e24a8080e..dc90db57a4625 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -17,16 +17,13 @@ pub(crate) fn set_trace_value(trace_value: TraceValue) { *global_trace_value = trace_value; } -pub(crate) fn init_tracing(sender: ClientSender) { +pub(crate) fn init_tracing(sender: ClientSender, log_level: LogLevel) { LOGGING_SENDER .set(sender) .expect("logging sender should only be initialized once"); - // TODO(jane): Provide a way to set the log level - let subscriber = - tracing_subscriber::Registry::default().with(LogLayer.with_filter(LogFilter { - filter: LogLevel::Info, - })); + let subscriber = tracing_subscriber::Registry::default() + .with(LogLayer.with_filter(LogFilter { filter: log_level })); tracing::subscriber::set_global_default(subscriber) .expect("should be able to set global default subscriber"); From 580babaff1cf7d86028acc86e707b2da9ac7f0bc Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Sun, 9 Jun 2024 15:36:30 -0700 Subject: [PATCH 09/18] Write to stderr, use trace level as a filter, introduce RUFF_TRACE environment variable --- .../src/server/schedule/thread/pool.rs | 4 +- crates/ruff_server/src/trace.rs | 106 ++++++------------ 2 files changed, 35 insertions(+), 75 deletions(-) diff --git a/crates/ruff_server/src/server/schedule/thread/pool.rs b/crates/ruff_server/src/server/schedule/thread/pool.rs index 7d1f9a418fde4..ea654a11d2af4 100644 --- a/crates/ruff_server/src/server/schedule/thread/pool.rs +++ b/crates/ruff_server/src/server/schedule/thread/pool.rs @@ -56,10 +56,10 @@ impl Pool { let extant_tasks = Arc::new(AtomicUsize::new(0)); let mut handles = Vec::with_capacity(threads); - for _ in 0..threads { + for i in 0..threads { let handle = Builder::new(INITIAL_PRIORITY) .stack_size(STACK_SIZE) - .name("Worker".into()) + .name(format!("ruff:worker:{i}")) .spawn({ let extant_tasks = Arc::clone(&extant_tasks); let job_receiver: Receiver = job_receiver.clone(); diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index dc90db57a4625..bd71b9e4396b0 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -1,8 +1,8 @@ -use lsp_types::{notification::Notification, TraceValue}; +use lsp_types::TraceValue; use serde::Deserialize; use std::sync::{Mutex, OnceLock}; -use tracing::{level_filters::LevelFilter, Event}; -use tracing_subscriber::{layer::SubscriberExt, Layer}; +use tracing::level_filters::LevelFilter; +use tracing_subscriber::{fmt::time::Uptime, layer::SubscriberExt, Layer}; use crate::server::ClientSender; @@ -22,8 +22,15 @@ pub(crate) fn init_tracing(sender: ClientSender, log_level: LogLevel) { .set(sender) .expect("logging sender should only be initialized once"); - let subscriber = tracing_subscriber::Registry::default() - .with(LogLayer.with_filter(LogFilter { filter: log_level })); + let subscriber = tracing_subscriber::Registry::default().with( + tracing_subscriber::fmt::layer() + .with_timer(Uptime::default()) + .with_thread_names(true) + .with_ansi(false) + .with_writer(|| Box::new(std::io::stderr())) + .with_filter(TraceLevelFilter) + .with_filter(LogLevelFilter { filter: log_level }), + ); tracing::subscriber::set_global_default(subscriber) .expect("should be able to set global default subscriber"); @@ -37,46 +44,28 @@ pub(crate) enum LogLevel { Warn, Info, Debug, + Trace, } impl LogLevel { - fn from_trace_level(level: tracing::Level) -> Self { - match level { - tracing::Level::ERROR => Self::Error, - tracing::Level::WARN => Self::Warn, - tracing::Level::INFO => Self::Info, - _ => Self::Debug, - } - } - - fn message_type(self) -> lsp_types::MessageType { - match self { - Self::Error => lsp_types::MessageType::ERROR, - Self::Warn => lsp_types::MessageType::WARNING, - Self::Info => lsp_types::MessageType::INFO, - // TODO(jane): LSP `0.3.18` will introduce `MessageType::DEBUG`, - // and we should consider using that. - Self::Debug => lsp_types::MessageType::LOG, - } - } - fn trace_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, } } } -struct LogLayer; - -struct LogFilter { +struct LogLevelFilter { filter: LogLevel, } -impl tracing_subscriber::layer::Filter for LogFilter { +struct TraceLevelFilter; + +impl tracing_subscriber::layer::Filter for LogLevelFilter { fn enabled( &self, meta: &tracing::Metadata<'_>, @@ -96,53 +85,24 @@ impl tracing_subscriber::layer::Filter for LogFilter { } } -impl tracing_subscriber::Layer for LogLayer { - fn register_callsite( - &self, - meta: &'static tracing::Metadata<'static>, - ) -> tracing::subscriber::Interest { - if meta.is_event() && meta.fields().iter().any(|field| field.name() == "message") { - tracing::subscriber::Interest::always() - } else { - tracing::subscriber::Interest::never() - } - } - - fn on_event( +impl tracing_subscriber::layer::Filter for TraceLevelFilter { + fn enabled( &self, - event: &Event<'_>, - _ctx: tracing_subscriber::layer::Context<'_, tracing_subscriber::Registry>, - ) { - let mut message_visitor = - LogMessageVisitor(LogLevel::from_trace_level(*event.metadata().level())); - event.record(&mut message_visitor); - } -} - -#[derive(Default)] -struct LogMessageVisitor(LogLevel); - -impl tracing::field::Visit for LogMessageVisitor { - fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { - if field.name() == "message" { - log(format!("{value:?}"), self.0); - } + _: &tracing::Metadata<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + trace_value() != lsp_types::TraceValue::Off } } #[inline] -fn log(message: String, level: LogLevel) { - let _ = LOGGING_SENDER - .get() - .expect("logging channel should be initialized") - .send(lsp_server::Message::Notification( - lsp_server::Notification { - method: lsp_types::notification::LogMessage::METHOD.into(), - params: serde_json::to_value(lsp_types::LogMessageParams { - typ: level.message_type(), - message, - }) - .expect("log notification should serialize"), - }, - )); +fn trace_value() -> lsp_types::TraceValue { + std::env::var("RUFF_TRACE") + .ok() + .and_then(|trace| serde_json::from_value(serde_json::Value::String(trace)).ok()) + .unwrap_or_else(|| { + *TRACE_VALUE + .lock() + .expect("trace value mutex should be available") + }) } From c303c8752ee8e0c3dd5331711ed148c854ed19d5 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Sun, 9 Jun 2024 15:37:16 -0700 Subject: [PATCH 10/18] Move RUFF_TRACE key to const --- crates/ruff_server/src/trace.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index bd71b9e4396b0..2eed056a0cbc2 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -6,6 +6,8 @@ use tracing_subscriber::{fmt::time::Uptime, layer::SubscriberExt, Layer}; use crate::server::ClientSender; +const TRACE_ENV_KEY: &str = "RUFF_TRACE"; + static LOGGING_SENDER: OnceLock = OnceLock::new(); static TRACE_VALUE: Mutex = Mutex::new(lsp_types::TraceValue::Off); @@ -97,7 +99,7 @@ impl tracing_subscriber::layer::Filter for TraceLevelFilter { #[inline] fn trace_value() -> lsp_types::TraceValue { - std::env::var("RUFF_TRACE") + std::env::var(TRACE_ENV_KEY) .ok() .and_then(|trace| serde_json::from_value(serde_json::Value::String(trace)).ok()) .unwrap_or_else(|| { From 3c4b4b54e2fc37bd8e449f7cebcdace9707768f2 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Sun, 9 Jun 2024 16:01:13 -0700 Subject: [PATCH 11/18] Add support for log file setting --- crates/ruff_server/src/server.rs | 1 + crates/ruff_server/src/session/settings.rs | 14 ++++++-- crates/ruff_server/src/trace.rs | 39 ++++++++++++++++++++-- 3 files changed, 49 insertions(+), 5 deletions(-) diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index d5d8bf885cc1f..77ad30fb628f2 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -83,6 +83,7 @@ impl Server { global_settings .log_level() .unwrap_or(crate::trace::LogLevel::Info), + global_settings.log_file(), ); let mut workspace_for_url = |url: lsp_types::Url| { diff --git a/crates/ruff_server/src/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 6d07d9b4b0d8a..8d9fcb2308e60 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -70,7 +70,10 @@ pub(crate) struct ClientSettings { exclude: Option>, line_length: Option, configuration_preference: Option, - pub(crate) log_level: Option, + // These settings are only needed for tracing, and are only read from the global configuration. + // These will not be in the resolved settings. + log_level: Option, + log_file: Option, } /// This is a direct representation of the workspace settings schema, @@ -179,12 +182,19 @@ impl AllSettings { } impl ClientSettings { - /// Log level is taken directly from client settings, since we need it before + /// `logLevel` is taken directly from client settings, since we need it before /// we resolve workspace settings. Additionally, this setting should only be set in global settings, /// and any log level set in workspace settings will be ignored. pub(crate) fn log_level(&self) -> Option { self.log_level } + + /// `logFile` is taken directly from client settings, since we need it before + /// we resolve workspace settings. Additionally, this setting should only be set in global settings, + /// and any log level set in workspace settings will be ignored. + pub(crate) fn log_file(&self) -> Option<&std::path::Path> { + self.log_file.as_deref() + } } impl ResolvedClientSettings { diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index 2eed056a0cbc2..3692824185150 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -1,6 +1,9 @@ use lsp_types::TraceValue; use serde::Deserialize; -use std::sync::{Mutex, OnceLock}; +use std::{ + path::PathBuf, + sync::{Mutex, OnceLock}, +}; use tracing::level_filters::LevelFilter; use tracing_subscriber::{fmt::time::Uptime, layer::SubscriberExt, Layer}; @@ -19,7 +22,11 @@ pub(crate) fn set_trace_value(trace_value: TraceValue) { *global_trace_value = trace_value; } -pub(crate) fn init_tracing(sender: ClientSender, log_level: LogLevel) { +pub(crate) fn init_tracing( + sender: ClientSender, + log_level: LogLevel, + log_file: Option<&std::path::Path>, +) { LOGGING_SENDER .set(sender) .expect("logging sender should only be initialized once"); @@ -29,7 +36,7 @@ pub(crate) fn init_tracing(sender: ClientSender, log_level: LogLevel) { .with_timer(Uptime::default()) .with_thread_names(true) .with_ansi(false) - .with_writer(|| Box::new(std::io::stderr())) + .with_writer(TracingWriter::new(log_file)) .with_filter(TraceLevelFilter) .with_filter(LogLevelFilter { filter: log_level }), ); @@ -97,6 +104,32 @@ impl tracing_subscriber::layer::Filter for TraceLevelFilter { } } +struct TracingWriter(Option); + +impl TracingWriter { + fn new(file: Option<&std::path::Path>) -> TracingWriter { + Self(file.map(std::path::Path::to_path_buf)) + } +} + +impl tracing_subscriber::fmt::MakeWriter<'_> for TracingWriter { + type Writer = Box; + + fn make_writer(&self) -> Self::Writer { + if let Some(file) = self.0.as_ref().and_then(|path| { + std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(path) + .ok() + }) { + Box::new(file) + } else { + Box::new(std::io::stderr()) + } + } +} + #[inline] fn trace_value() -> lsp_types::TraceValue { std::env::var(TRACE_ENV_KEY) From 3e0054519acc3aca0eab489a58870d9c7cd9e452 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Sun, 9 Jun 2024 21:54:55 -0700 Subject: [PATCH 12/18] Update tests --- crates/ruff_server/src/session/settings.rs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/crates/ruff_server/src/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 8d9fcb2308e60..9e15dcbcbdc40 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -445,6 +445,7 @@ mod tests { line_length: None, configuration_preference: None, log_level: None, + log_file: None, }, workspace_settings: [ WorkspaceSettings { @@ -494,6 +495,7 @@ mod tests { line_length: None, configuration_preference: None, log_level: None, + log_file: None, }, workspace: Url { scheme: "file", @@ -556,6 +558,7 @@ mod tests { line_length: None, configuration_preference: None, log_level: None, + log_file: None, }, workspace: Url { scheme: "file", @@ -699,6 +702,7 @@ mod tests { log_level: Some( Warn, ), + log_file: None, }, } "###); From 26ae0b637adb25dcbbbe8efd337b389db9533852 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Mon, 10 Jun 2024 10:20:55 -0700 Subject: [PATCH 13/18] Add module-level documentation --- crates/ruff_server/src/trace.rs | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index 3692824185150..7d58b79bb063f 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -1,3 +1,19 @@ +//! The tracing system for `ruff server`. +//! +//! Traces are controlled by the `logLevel` setting, along with the +//! trace level set through the LSP. On VS Code, the trace level can +//! also be set with `ruff.trace.server`. A trace level of `messages` or +//! `verbose` will enable tracing - otherwise, no traces will be shown. +//! +//! `logLevel` can be used to configure the level of tracing that is shown. +//! By default, `logLevel` is set to `"info"`. +//! +//! The server also supports the `RUFF_TRACE` environment variable, which will +//! override the trace value provided by the LSP client. Use this if there's no good way +//! to set the trace value through your editor's configuration. +//! +//! Tracing will write to `stderr` by default, which should appear in the logs for most LSP clients. +//! A `logFile` path can also be specified in the settings, and output will be directed there instead. use lsp_types::TraceValue; use serde::Deserialize; use std::{ From 4bd87cf167a8fcdce6bf383059afd66aedc66ace Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Mon, 10 Jun 2024 10:21:53 -0700 Subject: [PATCH 14/18] Document LogLevelFilter and TraceLevelFilter --- crates/ruff_server/src/trace.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index 7d58b79bb063f..bd4cb4b667652 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -84,10 +84,12 @@ impl LogLevel { } } +/// Filters out traces which have a log level lower than the `logLevel` set by the client. struct LogLevelFilter { filter: LogLevel, } +/// Filters out traces if the trace value set by the client is `off`. struct TraceLevelFilter; impl tracing_subscriber::layer::Filter for LogLevelFilter { From 1d5f886ae3e95567455ad381f8ca6e6038d5582c Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Mon, 10 Jun 2024 10:23:37 -0700 Subject: [PATCH 15/18] Show panics in tracing in addition to stderr --- crates/ruff_server/src/message.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/crates/ruff_server/src/message.rs b/crates/ruff_server/src/message.rs index 2807ce8b7baa4..66ad75542ccbb 100644 --- a/crates/ruff_server/src/message.rs +++ b/crates/ruff_server/src/message.rs @@ -32,8 +32,11 @@ pub(crate) fn init_messenger(client_sender: ClientSender) { } let backtrace = std::backtrace::Backtrace::force_capture(); + tracing::error!("{panic_info}\n{backtrace}"); #[allow(clippy::print_stderr)] { + // we also need to print to stderr directly in case tracing hasn't + // been initialized. eprintln!("{panic_info}\n{backtrace}"); } })); From 7d5175c8a3f2fbf09db7d4253336a83889cbae75 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Mon, 10 Jun 2024 10:26:52 -0700 Subject: [PATCH 16/18] Move tracing settings to dedicated struct --- crates/ruff_server/src/server.rs | 5 ++-- crates/ruff_server/src/session/settings.rs | 30 +++++++++------------- crates/ruff_server/src/trace.rs | 8 +++--- 3 files changed, 19 insertions(+), 24 deletions(-) diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index 77ad30fb628f2..0b1e5810ad8bf 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -81,9 +81,10 @@ impl Server { crate::trace::init_tracing( connection.make_sender(), global_settings - .log_level() + .tracing + .log_level .unwrap_or(crate::trace::LogLevel::Info), - global_settings.log_file(), + global_settings.tracing.log_file.as_deref(), ); let mut workspace_for_url = |url: lsp_types::Url| { diff --git a/crates/ruff_server/src/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 9e15dcbcbdc40..53b6ef1b17067 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -72,8 +72,18 @@ pub(crate) struct ClientSettings { configuration_preference: Option, // These settings are only needed for tracing, and are only read from the global configuration. // These will not be in the resolved settings. - log_level: Option, - log_file: Option, + #[serde(flatten)] + pub(crate) tracing: TracingSettings, +} + +/// Settings needed to initialize tracing. These will only be +/// read from the global configuration. +#[derive(Debug, Deserialize, Default)] +#[cfg_attr(test, derive(PartialEq, Eq))] +#[serde(rename_all = "camelCase")] +pub(crate) struct TracingSettings { + pub(crate) log_level: Option, + pub(crate) log_file: Option, } /// This is a direct representation of the workspace settings schema, @@ -181,22 +191,6 @@ impl AllSettings { } } -impl ClientSettings { - /// `logLevel` is taken directly from client settings, since we need it before - /// we resolve workspace settings. Additionally, this setting should only be set in global settings, - /// and any log level set in workspace settings will be ignored. - pub(crate) fn log_level(&self) -> Option { - self.log_level - } - - /// `logFile` is taken directly from client settings, since we need it before - /// we resolve workspace settings. Additionally, this setting should only be set in global settings, - /// and any log level set in workspace settings will be ignored. - pub(crate) fn log_file(&self) -> Option<&std::path::Path> { - self.log_file.as_deref() - } -} - impl ResolvedClientSettings { /// Resolves a series of client settings, prioritizing workspace settings over global settings. /// Any fields not specified by either are set to their defaults. diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index bd4cb4b667652..0c82a972d7f34 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -1,17 +1,17 @@ //! The tracing system for `ruff server`. -//! +//! //! Traces are controlled by the `logLevel` setting, along with the //! trace level set through the LSP. On VS Code, the trace level can //! also be set with `ruff.trace.server`. A trace level of `messages` or //! `verbose` will enable tracing - otherwise, no traces will be shown. -//! +//! //! `logLevel` can be used to configure the level of tracing that is shown. //! By default, `logLevel` is set to `"info"`. -//! +//! //! The server also supports the `RUFF_TRACE` environment variable, which will //! override the trace value provided by the LSP client. Use this if there's no good way //! to set the trace value through your editor's configuration. -//! +//! //! Tracing will write to `stderr` by default, which should appear in the logs for most LSP clients. //! A `logFile` path can also be specified in the settings, and output will be directed there instead. use lsp_types::TraceValue; From 8a8caa59968bf3072ea4c4b5e189772418df2115 Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Mon, 10 Jun 2024 10:31:16 -0700 Subject: [PATCH 17/18] Use BoxMakeWriter --- crates/ruff_server/src/trace.rs | 50 ++++++++++++--------------------- 1 file changed, 18 insertions(+), 32 deletions(-) diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs index 0c82a972d7f34..9910651210931 100644 --- a/crates/ruff_server/src/trace.rs +++ b/crates/ruff_server/src/trace.rs @@ -16,12 +16,13 @@ //! A `logFile` path can also be specified in the settings, and output will be directed there instead. use lsp_types::TraceValue; use serde::Deserialize; -use std::{ - path::PathBuf, - sync::{Mutex, OnceLock}, -}; +use std::sync::{Arc, Mutex, OnceLock}; use tracing::level_filters::LevelFilter; -use tracing_subscriber::{fmt::time::Uptime, layer::SubscriberExt, Layer}; +use tracing_subscriber::{ + fmt::{time::Uptime, writer::BoxMakeWriter}, + layer::SubscriberExt, + Layer, +}; use crate::server::ClientSender; @@ -47,12 +48,23 @@ pub(crate) fn init_tracing( .set(sender) .expect("logging sender should only be initialized once"); + let log_file = log_file.and_then(|path| { + std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(path) + .ok() + }); + let subscriber = tracing_subscriber::Registry::default().with( tracing_subscriber::fmt::layer() .with_timer(Uptime::default()) .with_thread_names(true) .with_ansi(false) - .with_writer(TracingWriter::new(log_file)) + .with_writer(match log_file { + Some(file) => BoxMakeWriter::new(Arc::new(file)), + None => BoxMakeWriter::new(std::io::stderr), + }) .with_filter(TraceLevelFilter) .with_filter(LogLevelFilter { filter: log_level }), ); @@ -122,32 +134,6 @@ impl tracing_subscriber::layer::Filter for TraceLevelFilter { } } -struct TracingWriter(Option); - -impl TracingWriter { - fn new(file: Option<&std::path::Path>) -> TracingWriter { - Self(file.map(std::path::Path::to_path_buf)) - } -} - -impl tracing_subscriber::fmt::MakeWriter<'_> for TracingWriter { - type Writer = Box; - - fn make_writer(&self) -> Self::Writer { - if let Some(file) = self.0.as_ref().and_then(|path| { - std::fs::OpenOptions::new() - .create(true) - .append(true) - .open(path) - .ok() - }) { - Box::new(file) - } else { - Box::new(std::io::stderr()) - } - } -} - #[inline] fn trace_value() -> lsp_types::TraceValue { std::env::var(TRACE_ENV_KEY) From f5d35ddb119e47d72296a1e20943894efe2ee06a Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Mon, 10 Jun 2024 10:32:02 -0700 Subject: [PATCH 18/18] Update tests --- crates/ruff_server/src/session/settings.rs | 28 ++++++++++++++-------- 1 file changed, 18 insertions(+), 10 deletions(-) diff --git a/crates/ruff_server/src/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 53b6ef1b17067..06a08ddfe1dd1 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -438,8 +438,10 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, - log_level: None, - log_file: None, + tracing: TracingSettings { + log_level: None, + log_file: None, + }, }, workspace_settings: [ WorkspaceSettings { @@ -488,8 +490,10 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, - log_level: None, - log_file: None, + tracing: TracingSettings { + log_level: None, + log_file: None, + }, }, workspace: Url { scheme: "file", @@ -551,8 +555,10 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, - log_level: None, - log_file: None, + tracing: TracingSettings { + log_level: None, + log_file: None, + }, }, workspace: Url { scheme: "file", @@ -693,10 +699,12 @@ mod tests { ), ), configuration_preference: None, - log_level: Some( - Warn, - ), - log_file: None, + tracing: TracingSettings { + log_level: Some( + Warn, + ), + log_file: None, + }, }, } "###);