From 507f5c1137d18a30057ce4708ba6fc0656570dac Mon Sep 17 00:00:00 2001 From: Jane Lewis Date: Tue, 11 Jun 2024 11:29:47 -0700 Subject: [PATCH] `ruff server`: Tracing system now respects log level and trace level, with options to log to a file (#11747) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary Fixes #10968. Fixes #11545. The server's tracing system has been rewritten from the ground up. The server now has trace level and log level settings which restrict the tracing events and spans that get logged. * A `logLevel` setting has been added, which lets a user set the log level. By default, it is set to `"info"`. * A `logFile` setting has also been added, which lets the user supply an optional file to send tracing output (it does not have to exist as a file yet). By default, if this is unset, tracing output will be sent to `stderr`. * A `$/setTrace` handler has also been added, and we also set the trace level from the initialization options. For editors without direct support for tracing, the environment variable `RUFF_TRACE` can override the trace level. * Small changes have been made to how we display tracing output. We no longer use `tracing-tree`, and instead use `tracing_subscriber::fmt::Layer` to format output. Thread names are now included in traces, and I've made some adjustment to thread worker names to be more useful. ## Test Plan In VS Code, with `ruff.trace.server` set to its default value, no logs from Ruff should appear. After changing `ruff.trace.server` to either `messages` or `verbose`, you should see log messages at `info` level or higher appear in Ruff's output: Screenshot 2024-06-10 at 10 35 04 AM In Helix, by default, no logs from Ruff should appear. To set the trace level in Helix, you'll need to modify your language configuration as follows: ```toml [language-server.ruff] command = "/Users/jane/astral/ruff/target/debug/ruff" args = ["server", "--preview"] environment = { "RUFF_TRACE" = "messages" } ``` After doing this, logs of `info` level or higher should be visible in Helix: Screenshot 2024-06-10 at 10 39 26 AM You can use `:log-open` to quickly open the Helix log file. In Neovim, by default, no logs from Ruff should appear. To set the trace level in Neovim, you'll need to modify your configuration as follows: ```lua require('lspconfig').ruff.setup { cmd = {"/path/to/debug/executable", "server", "--preview"}, cmd_env = { RUFF_TRACE = "messages" } } ``` You should see logs appear in `:LspLog` that look like the following: Screenshot 2024-06-11 at 11 24 01 AM You can adjust `logLevel` and `logFile` in `settings`: ```lua require('lspconfig').ruff.setup { cmd = {"/path/to/debug/executable", "server", "--preview"}, cmd_env = { RUFF_TRACE = "messages" }, settings = { logLevel = "debug", logFile = "your/log/file/path/log.txt" } } ``` The `logLevel` and `logFile` can also be set in Helix like so: ```toml [language-server.ruff.config.settings] logLevel = "debug" logFile = "your/log/file/path/log.txt" ``` Even if this log file does not exist, it should now be created and written to after running the server: Screenshot 2024-06-10 at 10 43 44 AM --- Cargo.lock | 3 +- crates/ruff/Cargo.toml | 2 - 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/message.rs | 6 + crates/ruff_server/src/server.rs | 13 ++ crates/ruff_server/src/server/api.rs | 3 + .../src/server/api/notifications.rs | 2 + .../src/server/api/notifications/set_trace.rs | 23 +++ .../src/server/schedule/thread/pool.rs | 4 +- crates/ruff_server/src/session/settings.rs | 38 ++++- crates/ruff_server/src/trace.rs | 147 ++++++++++++++++++ 14 files changed, 241 insertions(+), 78 deletions(-) create mode 100644 crates/ruff_server/src/server/api/notifications/set_trace.rs create mode 100644 crates/ruff_server/src/trace.rs diff --git a/Cargo.lock b/Cargo.lock index 85317582a93b9..ea95b29c80b88 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1939,8 +1939,6 @@ dependencies = [ "tikv-jemallocator", "toml", "tracing", - "tracing-subscriber", - "tracing-tree", "walkdir", "wild", ] @@ -2340,6 +2338,7 @@ dependencies = [ "serde_json", "shellexpand", "tracing", + "tracing-subscriber", "walkdir", ] diff --git a/crates/ruff/Cargo.toml b/crates/ruff/Cargo.toml index ce24a1cee33fb..955922b48e92f 100644 --- a/crates/ruff/Cargo.toml +++ b/crates/ruff/Cargo.toml @@ -53,8 +53,6 @@ tempfile = { workspace = true } 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/message.rs b/crates/ruff_server/src/message.rs index bd759feb1142e..66ad75542ccbb 100644 --- a/crates/ruff_server/src/message.rs +++ b/crates/ruff_server/src/message.rs @@ -33,6 +33,12 @@ 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}"); + } })); } diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index 76c5f1a55f6c2..0b1e5810ad8bf 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -63,6 +63,10 @@ impl Server { crate::version(), )?; + if let Some(trace) = init_params.trace { + crate::trace::set_trace_value(trace); + } + crate::message::init_messenger(connection.make_sender()); let AllSettings { @@ -74,6 +78,15 @@ impl Server { .unwrap_or_else(|| serde_json::Value::Object(serde_json::Map::default())), ); + crate::trace::init_tracing( + connection.make_sender(), + global_settings + .tracing + .log_level + .unwrap_or(crate::trace::LogLevel::Info), + global_settings.tracing.log_file.as_deref(), + ); + 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/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/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/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 8fc98572bf139..06a08ddfe1dd1 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -70,6 +70,20 @@ pub(crate) struct ClientSettings { exclude: Option>, line_length: Option, 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. + #[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, @@ -424,6 +438,10 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, + tracing: TracingSettings { + log_level: None, + log_file: None, + }, }, workspace_settings: [ WorkspaceSettings { @@ -472,6 +490,10 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, + tracing: TracingSettings { + log_level: None, + log_file: None, + }, }, workspace: Url { scheme: "file", @@ -533,6 +555,10 @@ mod tests { exclude: None, line_length: None, configuration_preference: None, + tracing: TracingSettings { + log_level: None, + log_file: None, + }, }, workspace: Url { scheme: "file", @@ -588,7 +614,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: ConfigurationPreference::default(), - } + }, } ); let path = @@ -619,7 +645,7 @@ mod tests { exclude: None, line_length: None, configuration_preference: ConfigurationPreference::EditorFirst, - } + }, } ); } @@ -673,6 +699,12 @@ mod tests { ), ), configuration_preference: None, + tracing: TracingSettings { + log_level: Some( + Warn, + ), + log_file: None, + }, }, } "###); @@ -703,7 +735,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 new file mode 100644 index 0000000000000..9910651210931 --- /dev/null +++ b/crates/ruff_server/src/trace.rs @@ -0,0 +1,147 @@ +//! 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::sync::{Arc, Mutex, OnceLock}; +use tracing::level_filters::LevelFilter; +use tracing_subscriber::{ + fmt::{time::Uptime, writer::BoxMakeWriter}, + 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); + +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, + log_level: LogLevel, + log_file: Option<&std::path::Path>, +) { + LOGGING_SENDER + .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(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 }), + ); + + 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 { + #[default] + Error, + Warn, + Info, + Debug, + Trace, +} + +impl LogLevel { + 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, + } + } +} + +/// 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 { + fn enabled( + &self, + meta: &tracing::Metadata<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + let filter = if meta.target().starts_with("ruff") { + self.filter.trace_level() + } else { + tracing::Level::INFO + }; + + meta.level() <= &filter + } + + fn max_level_hint(&self) -> Option { + Some(LevelFilter::from_level(self.filter.trace_level())) + } +} + +impl tracing_subscriber::layer::Filter for TraceLevelFilter { + fn enabled( + &self, + _: &tracing::Metadata<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + trace_value() != lsp_types::TraceValue::Off + } +} + +#[inline] +fn trace_value() -> lsp_types::TraceValue { + std::env::var(TRACE_ENV_KEY) + .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") + }) +}