ruff server: Tracing system now respects log level and trace level, with options to log to a file

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 }
 

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<ExitStatus> {
+pub(crate) fn run_server(preview: bool, worker_threads: NonZeroUsize) -> Result<ExitStatus> {
     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<S> Filter<S> 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<LevelFilter> {
-        Some(LevelFilter::from_level(self.trace_level))
-    }
-}

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<ExitS
     }
 }
 
-fn server(args: ServerCommand, log_level: LogLevel) -> Result<ExitStatus> {
+fn server(args: ServerCommand) -> Result<ExitStatus> {
     let ServerCommand { preview } = args;
 
     let four = NonZeroUsize::new(4).unwrap();
@@ -224,7 +224,7 @@ fn server(args: ServerCommand, log_level: LogLevel) -> Result<ExitStatus> {
     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<ExitStatus> {

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]

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";

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}");
+        }
     }));
 }
 

crates/ruff_server/src/server.rs

@@ -63,7 +63,12 @@ impl Server {
             crate::version(),
         )?;
 
+        if let Some(trace) = init_params.trace {
+            crate::trace::set_trace_value(trace);
+        }
+
         crate::message::init_messenger(connection.make_sender());
+        crate::trace::init_tracing(connection.make_sender());
 
         let AllSettings {
             global_settings,

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::<notification::DidCloseNotebook>(notif)
         }
+        notification::SetTrace::METHOD => {
+            local_notification_task::<notification::SetTrace>(notif)
+        }
         method => {
             tracing::warn!("Received notification {method} which does not have a handler.");
             return Task::nothing();

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;

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(())
+    }
+}

crates/ruff_server/src/trace.rs

@@ -0,0 +1,151 @@
+use lsp_types::{notification::Notification, TraceValue};
+use serde::Deserialize;
+use std::sync::{Mutex, OnceLock};
+use tracing::{level_filters::LevelFilter, Event};
+use tracing_subscriber::{layer::SubscriberExt, Layer};
+
+use crate::server::ClientSender;
+
+static LOGGING_SENDER: OnceLock<ClientSender> = OnceLock::new();
+
+static TRACE_VALUE: Mutex<lsp_types::TraceValue> = 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) {
+    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,
+        }));
+
+    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,
+}
+
+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;
+
+struct LogFilter {
+    filter: LogLevel,
+}
+
+impl<S> tracing_subscriber::layer::Filter<S> for LogFilter {
+    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<tracing::level_filters::LevelFilter> {
+        Some(LevelFilter::from_level(self.filter.trace_level()))
+    }
+}
+
+impl tracing_subscriber::Layer<tracing_subscriber::Registry> 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(
+        &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"),
+            },
+        ));
+}