From 1447553bc2ad3b38f0149ceafdff3ea4ce4bc383 Mon Sep 17 00:00:00 2001 From: Dhruv Manilawala Date: Wed, 8 Jan 2025 18:18:00 +0530 Subject: [PATCH] Improve logging system using `logLevel`, avoid trace value (#15232) ## Summary Refer to the VS Code PR (https://github.com/astral-sh/ruff-vscode/pull/659) for details on the change. This PR changes the following: 1. Add tracing span for both request (request id and method name) and notification (method name) handler 2. Remove the `RUFF_TRACE` environment variable. This was being used to turn on / off logging for the server 3. Similarly, remove reading the `trace` value from the initialization options 4. Remove handling the `$/setTrace` notification 5. Remove the specialized `TraceLogWriter` used for Zed and VS Code (https://github.com/astral-sh/ruff/pull/12564) Regarding the (5) for the Zed editor, the reason that was implemented was because there was no way of looking at the stderr messages in the editor which has been changed. Now, it captures the stderr as part of the "Server Logs". (https://github.com/zed-industries/zed/blob/82492d74a8d0350cba66671c27e282a928fd4c85/crates/language_tools/src/lsp_log.rs#L548-L552) ### Question Regarding (1), I think having just a simple trace level message should be good for now as the spans are not hierarchical. This could be tackled with #12744. The difference between the two:
Using tracing::trace

``` 0.019243416s DEBUG ThreadId(08) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 0.026398750s INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff 0.026802125s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen" 0.026930666s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen" 0.026962333s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (1) 0.027042875s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (2) 0.027097500s TRACE ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (3) 0.027107458s DEBUG ruff:worker:0 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 0.027123541s DEBUG ruff:worker:3 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py 0.027514875s INFO ruff:main ruff_server::server: Configuration file watcher successfully registered 0.285689833s TRACE ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (4) 45.741101666s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didClose" 47.108745500s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen" 47.109802041s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (5) 47.109926958s TRACE ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (6) 47.110027791s DEBUG ruff:worker:6 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 51.863679125s TRACE ruff:main ruff_server::server::api: Received request "textDocument/hover" (7) ```

Using tracing::trace_span

Only logging the enter event: ``` 0.018638750s DEBUG ThreadId(11) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 0.025895791s INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff 0.026378791s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter 0.026531208s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter 0.026567583s TRACE ruff:main request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter 0.026652541s TRACE ruff:main request{id=2 method="textDocument/diagnostic"}: ruff_server::server::api: enter 0.026711041s DEBUG ruff:worker:2 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py 0.026729166s DEBUG ruff:worker:1 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 0.027023083s INFO ruff:main ruff_server::server: Configuration file watcher successfully registered 5.197554750s TRACE ruff:main notification{method="textDocument/didClose"}: ruff_server::server::api: enter 6.534458000s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter 6.535027958s TRACE ruff:main request{id=3 method="textDocument/diagnostic"}: ruff_server::server::api: enter 6.535271166s DEBUG ruff:worker:3 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py 6.544240583s TRACE ruff:main request{id=4 method="textDocument/codeAction"}: ruff_server::server::api: enter 7.049692458s TRACE ruff:main request{id=5 method="textDocument/codeAction"}: ruff_server::server::api: enter 7.508142541s TRACE ruff:main request{id=6 method="textDocument/hover"}: ruff_server::server::api: enter 7.872421958s TRACE ruff:main request{id=7 method="textDocument/hover"}: ruff_server::server::api: enter 8.024498583s TRACE ruff:main request{id=8 method="textDocument/codeAction"}: ruff_server::server::api: enter 13.895063666s TRACE ruff:main request{id=9 method="textDocument/codeAction"}: ruff_server::server::api: enter 14.774706083s TRACE ruff:main request{id=10 method="textDocument/hover"}: ruff_server::server::api: enter 16.058918958s TRACE ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter 16.060562208s TRACE ruff:main request{id=11 method="textDocument/diagnostic"}: ruff_server::server::api: enter 16.061109083s DEBUG ruff:worker:8 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 21.561742875s TRACE ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter 21.563573791s TRACE ruff:main request{id=12 method="textDocument/diagnostic"}: ruff_server::server::api: enter 21.564206750s DEBUG ruff:worker:4 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 21.826691375s TRACE ruff:main request{id=13 method="textDocument/codeAction"}: ruff_server::server::api: enter 22.091080125s TRACE ruff:main request{id=14 method="textDocument/codeAction"}: ruff_server::server::api: enter ```

**Todo** - [x] Update documentation (I'll be adding a troubleshooting section under "Editors" as a follow-up which is for all editors) - [x] Check for backwards compatibility. I don't think this should break backwards compatibility as it's mainly targeted towards improving the debugging experience. ~**Before I go on to updating the documentation, I'd appreciate initial review on the chosen approach.**~ resolves: #14959 ## Test Plan Refer to the test plan in https://github.com/astral-sh/ruff-vscode/pull/659. Example logs at `debug` level: ``` 0.010770083s DEBUG ThreadId(15) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 0.018101916s INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff 0.018559916s DEBUG ruff:worker:4 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 0.018992375s INFO ruff:main ruff_server::server: Configuration file watcher successfully registered 23.408802375s DEBUG ruff:worker:11 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 24.329127416s DEBUG ruff:worker:6 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py ``` Example logs at `trace` level: ``` 0.010296375s DEBUG ThreadId(13) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 0.017422583s INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff 0.018034458s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter 0.018199708s TRACE ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter 0.018251167s DEBUG ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 0.018528708s INFO ruff:main ruff_server::server: Configuration file watcher successfully registered 1.611798417s TRACE ruff:worker:1 request{id=2 method="textDocument/codeAction"}: ruff_server::server::api: enter 1.861757542s TRACE ruff:worker:4 request{id=3 method="textDocument/codeAction"}: ruff_server::server::api: enter 7.027361792s TRACE ruff:worker:2 request{id=4 method="textDocument/codeAction"}: ruff_server::server::api: enter 7.851361500s TRACE ruff:worker:5 request{id=5 method="textDocument/codeAction"}: ruff_server::server::api: enter 7.901690875s TRACE ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter 7.903063167s TRACE ruff:worker:10 request{id=6 method="textDocument/diagnostic"}: ruff_server::server::api: enter 7.903183500s DEBUG ruff:worker:10 request{id=6 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 8.702385292s TRACE ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter 8.704106625s TRACE ruff:worker:3 request{id=7 method="textDocument/diagnostic"}: ruff_server::server::api: enter 8.704304875s DEBUG ruff:worker:3 request{id=7 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py 8.966853458s TRACE ruff:worker:9 request{id=8 method="textDocument/codeAction"}: ruff_server::server::api: enter 9.229622792s TRACE ruff:worker:6 request{id=9 method="textDocument/codeAction"}: ruff_server::server::api: enter 10.513111583s TRACE ruff:worker:7 request{id=10 method="textDocument/codeAction"}: ruff_server::server::api: enter ``` --- crates/red_knot_server/src/lib.rs | 2 +- crates/red_knot_server/src/logging.rs | 114 +++++++++ crates/red_knot_server/src/server.rs | 13 +- crates/red_knot_server/src/server/api.rs | 3 - .../src/server/api/notifications.rs | 2 - .../src/server/api/notifications/set_trace.rs | 25 -- .../red_knot_server/src/session/settings.rs | 2 +- crates/red_knot_server/src/trace.rs | 221 ------------------ crates/ruff_server/src/lib.rs | 2 +- crates/ruff_server/src/logging.rs | 115 +++++++++ crates/ruff_server/src/server.rs | 14 +- crates/ruff_server/src/server/api.rs | 9 +- .../src/server/api/notifications.rs | 2 - .../src/server/api/notifications/set_trace.rs | 23 -- crates/ruff_server/src/session/settings.rs | 2 +- crates/ruff_server/src/trace.rs | 221 ------------------ docs/editors/setup.md | 27 ++- 17 files changed, 257 insertions(+), 540 deletions(-) create mode 100644 crates/red_knot_server/src/logging.rs delete mode 100644 crates/red_knot_server/src/server/api/notifications/set_trace.rs delete mode 100644 crates/red_knot_server/src/trace.rs create mode 100644 crates/ruff_server/src/logging.rs delete mode 100644 crates/ruff_server/src/server/api/notifications/set_trace.rs delete mode 100644 crates/ruff_server/src/trace.rs diff --git a/crates/red_knot_server/src/lib.rs b/crates/red_knot_server/src/lib.rs index eb29c7bbe428f..7c149a9ae81c8 100644 --- a/crates/red_knot_server/src/lib.rs +++ b/crates/red_knot_server/src/lib.rs @@ -11,10 +11,10 @@ use crate::server::Server; mod message; mod edit; +mod logging; mod server; mod session; mod system; -mod trace; pub(crate) const SERVER_NAME: &str = "red-knot"; pub(crate) const DIAGNOSTIC_NAME: &str = "Red Knot"; diff --git a/crates/red_knot_server/src/logging.rs b/crates/red_knot_server/src/logging.rs new file mode 100644 index 0000000000000..701e8b697e391 --- /dev/null +++ b/crates/red_knot_server/src/logging.rs @@ -0,0 +1,114 @@ +//! The logging system for `red_knot server`. +//! +//! Log messages are controlled by the `logLevel` setting which defaults to `"info"`. Log messages +//! are written 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 core::str; +use serde::Deserialize; +use std::{path::PathBuf, str::FromStr, sync::Arc}; +use tracing::level_filters::LevelFilter; +use tracing_subscriber::{ + fmt::{time::Uptime, writer::BoxMakeWriter}, + layer::SubscriberExt, + Layer, +}; + +pub(crate) fn init_logging(log_level: LogLevel, log_file: Option<&std::path::Path>) { + let log_file = log_file + .map(|path| { + // this expands `logFile` so that tildes and environment variables + // are replaced with their values, if possible. + if let Some(expanded) = shellexpand::full(&path.to_string_lossy()) + .ok() + .and_then(|path| PathBuf::from_str(&path).ok()) + { + expanded + } else { + path.to_path_buf() + } + }) + .and_then(|path| { + std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(&path) + .map_err(|err| { + #[allow(clippy::print_stderr)] + { + eprintln!( + "Failed to open file at {} for logging: {err}", + path.display() + ); + } + }) + .ok() + }); + + let logger = match log_file { + Some(file) => BoxMakeWriter::new(Arc::new(file)), + None => BoxMakeWriter::new(std::io::stderr), + }; + let subscriber = tracing_subscriber::Registry::default().with( + tracing_subscriber::fmt::layer() + .with_timer(Uptime::default()) + .with_thread_names(true) + .with_ansi(false) + .with_writer(logger) + .with_filter(LogLevelFilter { filter: log_level }), + ); + + tracing::subscriber::set_global_default(subscriber) + .expect("should be able to set global default subscriber"); +} + +/// The log level for the server as provided by the client during initialization. +/// +/// The default log level is `info`. +#[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 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, +} + +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("red_knot") { + 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())) + } +} diff --git a/crates/red_knot_server/src/server.rs b/crates/red_knot_server/src/server.rs index aa7e20e817df9..4a29644a8713c 100644 --- a/crates/red_knot_server/src/server.rs +++ b/crates/red_knot_server/src/server.rs @@ -51,10 +51,6 @@ 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 { @@ -66,14 +62,9 @@ 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), + crate::logging::init_logging( + global_settings.tracing.log_level.unwrap_or_default(), global_settings.tracing.log_file.as_deref(), - init_params.client_info.as_ref(), ); let mut workspace_for_url = |url: Url| { diff --git a/crates/red_knot_server/src/server/api.rs b/crates/red_knot_server/src/server/api.rs index be1aca8637dcd..ee56e1fe64a76 100644 --- a/crates/red_knot_server/src/server/api.rs +++ b/crates/red_knot_server/src/server/api.rs @@ -52,9 +52,6 @@ pub(super) fn notification<'a>(notif: server::Notification) -> Task<'a> { notification::DidCloseNotebookHandler::METHOD => { local_notification_task::(notif) } - notification::SetTraceHandler::METHOD => { - local_notification_task::(notif) - } method => { tracing::warn!("Received notification {method} which does not have a handler."); return Task::nothing(); diff --git a/crates/red_knot_server/src/server/api/notifications.rs b/crates/red_knot_server/src/server/api/notifications.rs index 33429547d4da6..9482c44cf8c10 100644 --- a/crates/red_knot_server/src/server/api/notifications.rs +++ b/crates/red_knot_server/src/server/api/notifications.rs @@ -3,11 +3,9 @@ mod did_close; mod did_close_notebook; mod did_open; mod did_open_notebook; -mod set_trace; pub(super) use did_change::DidChangeTextDocumentHandler; pub(super) use did_close::DidCloseTextDocumentHandler; pub(super) use did_close_notebook::DidCloseNotebookHandler; pub(super) use did_open::DidOpenTextDocumentHandler; pub(super) use did_open_notebook::DidOpenNotebookHandler; -pub(super) use set_trace::SetTraceHandler; diff --git a/crates/red_knot_server/src/server/api/notifications/set_trace.rs b/crates/red_knot_server/src/server/api/notifications/set_trace.rs deleted file mode 100644 index 5ff186b01db73..0000000000000 --- a/crates/red_knot_server/src/server/api/notifications/set_trace.rs +++ /dev/null @@ -1,25 +0,0 @@ -use lsp_types::notification::SetTrace; -use lsp_types::SetTraceParams; - -use crate::server::api::traits::{NotificationHandler, SyncNotificationHandler}; -use crate::server::client::{Notifier, Requester}; -use crate::server::Result; -use crate::session::Session; - -pub(crate) struct SetTraceHandler; - -impl NotificationHandler for SetTraceHandler { - type NotificationType = SetTrace; -} - -impl SyncNotificationHandler for SetTraceHandler { - fn run( - _session: &mut Session, - _notifier: Notifier, - _requester: &mut Requester, - params: SetTraceParams, - ) -> Result<()> { - crate::trace::set_trace_value(params.value); - Ok(()) - } -} diff --git a/crates/red_knot_server/src/session/settings.rs b/crates/red_knot_server/src/session/settings.rs index 0fccad470cbde..f140b9c4b1847 100644 --- a/crates/red_knot_server/src/session/settings.rs +++ b/crates/red_knot_server/src/session/settings.rs @@ -24,7 +24,7 @@ pub struct ClientSettings { #[cfg_attr(test, derive(PartialEq, Eq))] #[serde(rename_all = "camelCase")] pub(crate) struct TracingSettings { - pub(crate) log_level: Option, + pub(crate) log_level: Option, /// Path to the log file - tildes and environment variables are supported. pub(crate) log_file: Option, } diff --git a/crates/red_knot_server/src/trace.rs b/crates/red_knot_server/src/trace.rs deleted file mode 100644 index 7bd27747ef3fb..0000000000000 --- a/crates/red_knot_server/src/trace.rs +++ /dev/null @@ -1,221 +0,0 @@ -//! 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 core::str; -use lsp_server::{Message, Notification}; -use lsp_types::{ - notification::{LogTrace, Notification as _}, - ClientInfo, TraceValue, -}; -use serde::Deserialize; -use std::{ - io::{Error as IoError, ErrorKind, Write}, - path::PathBuf, - str::FromStr, - sync::{Arc, Mutex, OnceLock}, -}; -use tracing::level_filters::LevelFilter; -use tracing_subscriber::{ - fmt::{time::Uptime, writer::BoxMakeWriter, MakeWriter}, - 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; -} - -// A tracing writer that uses LSPs logTrace method. -struct TraceLogWriter; - -impl Write for TraceLogWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - let message = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?; - LOGGING_SENDER - .get() - .expect("logging sender should be initialized at this point") - .send(Message::Notification(Notification { - method: LogTrace::METHOD.to_owned(), - params: serde_json::json!({ - "message": message - }), - })) - .map_err(|e| IoError::new(ErrorKind::Other, e))?; - Ok(buf.len()) - } - - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } -} - -impl<'a> MakeWriter<'a> for TraceLogWriter { - type Writer = Self; - - fn make_writer(&'a self) -> Self::Writer { - Self - } -} - -pub(crate) fn init_tracing( - sender: ClientSender, - log_level: LogLevel, - log_file: Option<&std::path::Path>, - client: Option<&ClientInfo>, -) { - LOGGING_SENDER - .set(sender) - .expect("logging sender should only be initialized once"); - - let log_file = log_file - .map(|path| { - // this expands `logFile` so that tildes and environment variables - // are replaced with their values, if possible. - if let Some(expanded) = shellexpand::full(&path.to_string_lossy()) - .ok() - .and_then(|path| PathBuf::from_str(&path).ok()) - { - expanded - } else { - path.to_path_buf() - } - }) - .and_then(|path| { - std::fs::OpenOptions::new() - .create(true) - .append(true) - .open(&path) - .map_err(|err| { - #[allow(clippy::print_stderr)] - { - eprintln!( - "Failed to open file at {} for logging: {err}", - path.display() - ); - } - }) - .ok() - }); - - let logger = match log_file { - Some(file) => BoxMakeWriter::new(Arc::new(file)), - None => { - if client.is_some_and(|client| { - client.name.starts_with("Zed") || client.name.starts_with("Visual Studio Code") - }) { - BoxMakeWriter::new(TraceLogWriter) - } else { - BoxMakeWriter::new(std::io::stderr) - } - } - }; - let subscriber = tracing_subscriber::Registry::default().with( - tracing_subscriber::fmt::layer() - .with_timer(Uptime::default()) - .with_thread_names(true) - .with_ansi(false) - .with_writer(logger) - .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") - }) -} diff --git a/crates/ruff_server/src/lib.rs b/crates/ruff_server/src/lib.rs index ff0dc7ddb59b2..acde201469f8e 100644 --- a/crates/ruff_server/src/lib.rs +++ b/crates/ruff_server/src/lib.rs @@ -12,10 +12,10 @@ mod edit; mod fix; mod format; mod lint; +mod logging; mod resolve; 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/logging.rs b/crates/ruff_server/src/logging.rs new file mode 100644 index 0000000000000..1b23bff3bddf7 --- /dev/null +++ b/crates/ruff_server/src/logging.rs @@ -0,0 +1,115 @@ +//! The logging system for `ruff server`. +//! +//! Log messages are controlled by the `logLevel` setting which defaults to `"info"`. Log messages +//! are written 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 core::str; +use serde::Deserialize; +use std::{path::PathBuf, str::FromStr, sync::Arc}; +use tracing::level_filters::LevelFilter; +use tracing_subscriber::{ + fmt::{format::FmtSpan, time::Uptime, writer::BoxMakeWriter}, + layer::SubscriberExt, + Layer, +}; + +pub(crate) fn init_logging(log_level: LogLevel, log_file: Option<&std::path::Path>) { + let log_file = log_file + .map(|path| { + // this expands `logFile` so that tildes and environment variables + // are replaced with their values, if possible. + if let Some(expanded) = shellexpand::full(&path.to_string_lossy()) + .ok() + .and_then(|path| PathBuf::from_str(&path).ok()) + { + expanded + } else { + path.to_path_buf() + } + }) + .and_then(|path| { + std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(&path) + .map_err(|err| { + #[allow(clippy::print_stderr)] + { + eprintln!( + "Failed to open file at {} for logging: {err}", + path.display() + ); + } + }) + .ok() + }); + + let logger = match log_file { + Some(file) => BoxMakeWriter::new(Arc::new(file)), + None => BoxMakeWriter::new(std::io::stderr), + }; + let subscriber = tracing_subscriber::Registry::default().with( + tracing_subscriber::fmt::layer() + .with_timer(Uptime::default()) + .with_thread_names(true) + .with_ansi(false) + .with_writer(logger) + .with_span_events(FmtSpan::ENTER) + .with_filter(LogLevelFilter { filter: log_level }), + ); + + tracing::subscriber::set_global_default(subscriber) + .expect("should be able to set global default subscriber"); +} + +/// The log level for the server as provided by the client during initialization. +/// +/// The default log level is `info`. +#[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 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, +} + +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())) + } +} diff --git a/crates/ruff_server/src/server.rs b/crates/ruff_server/src/server.rs index b098b292e0c13..feba047efa1af 100644 --- a/crates/ruff_server/src/server.rs +++ b/crates/ruff_server/src/server.rs @@ -73,16 +73,11 @@ 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 InitializeParams { initialization_options, workspace_folders, - client_info, .. } = init_params; @@ -98,14 +93,9 @@ impl Server { workspace_settings, } = all_settings; - crate::trace::init_tracing( - connection.make_sender(), - global_settings - .tracing - .log_level - .unwrap_or(crate::trace::LogLevel::Info), + crate::logging::init_logging( + global_settings.tracing.log_level.unwrap_or_default(), global_settings.tracing.log_file.as_deref(), - client_info.as_ref(), ); let workspaces = Workspaces::from_workspace_folders( diff --git a/crates/ruff_server/src/server/api.rs b/crates/ruff_server/src/server/api.rs index 459ae8fe8f645..96414f1840e07 100644 --- a/crates/ruff_server/src/server/api.rs +++ b/crates/ruff_server/src/server/api.rs @@ -93,9 +93,6 @@ 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(); @@ -113,6 +110,7 @@ fn local_request_task<'a, R: traits::SyncRequestHandler>( ) -> super::Result> { let (id, params) = cast_request::(req)?; Ok(Task::local(|session, notifier, requester, responder| { + let _span = tracing::trace_span!("request", %id, method = R::METHOD).entered(); let result = R::run(session, notifier, requester, params); respond::(id, result, &responder); })) @@ -129,6 +127,7 @@ fn background_request_task<'a, R: traits::BackgroundDocumentRequestHandler>( return Box::new(|_, _| {}); }; Box::new(move |notifier, responder| { + let _span = tracing::trace_span!("request", %id, method = R::METHOD).entered(); let result = R::run_with_snapshot(snapshot, notifier, params); respond::(id, result, &responder); }) @@ -140,6 +139,7 @@ fn local_notification_task<'a, N: traits::SyncNotificationHandler>( ) -> super::Result> { let (id, params) = cast_notification::(notif)?; Ok(Task::local(move |session, notifier, requester, _| { + let _span = tracing::trace_span!("notification", method = N::METHOD).entered(); if let Err(err) = N::run(session, notifier, requester, params) { tracing::error!("An error occurred while running {id}: {err}"); show_err_msg!("Ruff encountered a problem. Check the logs for more details."); @@ -159,6 +159,7 @@ fn background_notification_thread<'a, N: traits::BackgroundDocumentNotificationH return Box::new(|_, _| {}); }; Box::new(move |notifier, _| { + let _span = tracing::trace_span!("notification", method = N::METHOD).entered(); if let Err(err) = N::run_with_snapshot(snapshot, notifier, params) { tracing::error!("An error occurred while running {id}: {err}"); show_err_msg!("Ruff encountered a problem. Check the logs for more details."); @@ -205,7 +206,7 @@ fn respond( Req: traits::RequestHandler, { if let Err(err) = &result { - tracing::error!("An error occurred with result ID {id}: {err}"); + tracing::error!("An error occurred with request ID {id}: {err}"); show_err_msg!("Ruff encountered a problem. Check the logs for more details."); } if let Err(err) = responder.respond(id, result) { diff --git a/crates/ruff_server/src/server/api/notifications.rs b/crates/ruff_server/src/server/api/notifications.rs index feb7771c22408..ade0c2fbd510f 100644 --- a/crates/ruff_server/src/server/api/notifications.rs +++ b/crates/ruff_server/src/server/api/notifications.rs @@ -8,7 +8,6 @@ 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; @@ -21,4 +20,3 @@ 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 deleted file mode 100644 index 9223d9e42b237..0000000000000 --- a/crates/ruff_server/src/server/api/notifications/set_trace.rs +++ /dev/null @@ -1,23 +0,0 @@ -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/session/settings.rs b/crates/ruff_server/src/session/settings.rs index 0f6a3806f5a46..50bbd413077a8 100644 --- a/crates/ruff_server/src/session/settings.rs +++ b/crates/ruff_server/src/session/settings.rs @@ -104,7 +104,7 @@ impl ClientSettings { #[cfg_attr(test, derive(PartialEq, Eq))] #[serde(rename_all = "camelCase")] pub(crate) struct TracingSettings { - pub(crate) log_level: Option, + pub(crate) log_level: Option, /// Path to the log file - tildes and environment variables are supported. pub(crate) log_file: Option, } diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs deleted file mode 100644 index 7bd27747ef3fb..0000000000000 --- a/crates/ruff_server/src/trace.rs +++ /dev/null @@ -1,221 +0,0 @@ -//! 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 core::str; -use lsp_server::{Message, Notification}; -use lsp_types::{ - notification::{LogTrace, Notification as _}, - ClientInfo, TraceValue, -}; -use serde::Deserialize; -use std::{ - io::{Error as IoError, ErrorKind, Write}, - path::PathBuf, - str::FromStr, - sync::{Arc, Mutex, OnceLock}, -}; -use tracing::level_filters::LevelFilter; -use tracing_subscriber::{ - fmt::{time::Uptime, writer::BoxMakeWriter, MakeWriter}, - 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; -} - -// A tracing writer that uses LSPs logTrace method. -struct TraceLogWriter; - -impl Write for TraceLogWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - let message = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?; - LOGGING_SENDER - .get() - .expect("logging sender should be initialized at this point") - .send(Message::Notification(Notification { - method: LogTrace::METHOD.to_owned(), - params: serde_json::json!({ - "message": message - }), - })) - .map_err(|e| IoError::new(ErrorKind::Other, e))?; - Ok(buf.len()) - } - - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } -} - -impl<'a> MakeWriter<'a> for TraceLogWriter { - type Writer = Self; - - fn make_writer(&'a self) -> Self::Writer { - Self - } -} - -pub(crate) fn init_tracing( - sender: ClientSender, - log_level: LogLevel, - log_file: Option<&std::path::Path>, - client: Option<&ClientInfo>, -) { - LOGGING_SENDER - .set(sender) - .expect("logging sender should only be initialized once"); - - let log_file = log_file - .map(|path| { - // this expands `logFile` so that tildes and environment variables - // are replaced with their values, if possible. - if let Some(expanded) = shellexpand::full(&path.to_string_lossy()) - .ok() - .and_then(|path| PathBuf::from_str(&path).ok()) - { - expanded - } else { - path.to_path_buf() - } - }) - .and_then(|path| { - std::fs::OpenOptions::new() - .create(true) - .append(true) - .open(&path) - .map_err(|err| { - #[allow(clippy::print_stderr)] - { - eprintln!( - "Failed to open file at {} for logging: {err}", - path.display() - ); - } - }) - .ok() - }); - - let logger = match log_file { - Some(file) => BoxMakeWriter::new(Arc::new(file)), - None => { - if client.is_some_and(|client| { - client.name.starts_with("Zed") || client.name.starts_with("Visual Studio Code") - }) { - BoxMakeWriter::new(TraceLogWriter) - } else { - BoxMakeWriter::new(std::io::stderr) - } - } - }; - let subscriber = tracing_subscriber::Registry::default().with( - tracing_subscriber::fmt::layer() - .with_timer(Uptime::default()) - .with_thread_names(true) - .with_ansi(false) - .with_writer(logger) - .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") - }) -} diff --git a/docs/editors/setup.md b/docs/editors/setup.md index efd856787e8da..0603a6b029b5d 100644 --- a/docs/editors/setup.md +++ b/docs/editors/setup.md @@ -92,13 +92,11 @@ require('lspconfig').pyright.setup { } ``` -By default, Ruff will not show any logs. To enable logging in Neovim, you'll need to set the -[`trace`](https://neovim.io/doc/user/lsp.html#vim.lsp.ClientConfig) setting to either `messages` or `verbose`, and use the -[`logLevel`](./settings.md#loglevel) setting to change the log level: +By default, the log level for Ruff is set to `info`. To change the log level, you can set the +[`logLevel`](./settings.md#loglevel) setting: ```lua require('lspconfig').ruff.setup { - trace = 'messages', init_options = { settings = { logLevel = 'debug', @@ -107,10 +105,16 @@ require('lspconfig').ruff.setup { } ``` -By default, this will write logs to stderr which will be available in Neovim's LSP client log file +By default, Ruff will write logs to stderr which will be available in Neovim's LSP client log file (`:lua vim.print(vim.lsp.get_log_path())`). It's also possible to divert these logs to a separate file with the [`logFile`](./settings.md#logfile) setting. +To view the trace logs between Neovim and Ruff, set the log level for Neovim's LSP client to `debug`: + +```lua +vim.lsp.set_log_level('debug') +``` + ## Vim The [`vim-lsp`](https://github.com/prabirshrestha/vim-lsp) plugin can be used to configure the Ruff Language Server in Vim. @@ -274,15 +278,13 @@ preview = false preview = true ``` -By default, Ruff does not log anything to Helix. To enable logging, set the `RUFF_TRACE` environment -variable to either `messages` or `verbose`, and use the [`logLevel`](./settings.md#loglevel) setting to change -the log level: +By default, the log level for Ruff is set to `info`. To change the log level, you can set the +[`logLevel`](./settings.md#loglevel) setting: ```toml [language-server.ruff] command = "ruff" args = ["server"] -environment = { "RUFF_TRACE" = "messages" } [language-server.ruff.config.settings] logLevel = "debug" @@ -290,10 +292,11 @@ logLevel = "debug" You can also divert Ruff's logs to a separate file with the [`logFile`](./settings.md#logfile) setting. -!!! note +To view the trace logs between Helix and Ruff, pass in the `-v` (verbose) flag when starting Helix: - Setting `RUFF_TRACE=verbose` does not enable Helix's verbose mode by itself. You'll need to run - Helix with `-v` for verbose logging. +```sh +hx -v path/to/file.py +``` ## Kate