From bf2c9a41cd7e5860a6aea8b9789893767ff4c1a5 Mon Sep 17 00:00:00 2001 From: Dhruv Manilawala Date: Wed, 26 Feb 2025 13:31:17 +0530 Subject: [PATCH] Avoid unnecessary info at non-trace server log level (#16389) ## Summary Currently, the log messages emitted by the server includes multiple information which isn't really required most of the time. Here's the current format: ``` 0.000755625s DEBUG main ruff_server::session::index::ruff_settings: Indexing settings for workspace: /Users/dhruv/playground/ruff 0.016334666s DEBUG ThreadId(10) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 0.019954541s INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff 0.020160416s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter 0.020209625s TRACE ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter 0.020228166s DEBUG ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/test.py 0.020359833s INFO ruff:main ruff_server::server: Configuration file watcher successfully registered ``` This PR updates the following: * Uses current timestamp (same as red-knot) for all log levels instead of the uptime value * Includes the target and thread names only at the trace level What this means is that the message is reduced to only important information at DEBUG level: ``` 2025-02-26 11:35:02.198375000 DEBUG Indexing settings for workspace: /Users/dhruv/playground/ruff 2025-02-26 11:35:02.209933000 DEBUG Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 2025-02-26 11:35:02.217165000 INFO Registering workspace: /Users/dhruv/playground/ruff 2025-02-26 11:35:02.217631000 DEBUG Included path via `include`: /Users/dhruv/playground/ruff/lsp/test.py 2025-02-26 11:35:02.217684000 INFO Configuration file watcher successfully registered ``` while still showing the other information (thread names and target) at trace level: ``` 2025-02-26 11:35:27.819617000 DEBUG main ruff_server::session::index::ruff_settings: Indexing settings for workspace: /Users/dhruv/playground/ruff 2025-02-26 11:35:27.830500000 DEBUG ThreadId(11) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode 2025-02-26 11:35:27.837212000 INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff 2025-02-26 11:35:27.837714000 TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter 2025-02-26 11:35:27.838019000 INFO ruff:main ruff_server::server: Configuration file watcher successfully registered 2025-02-26 11:35:27.838084000 TRACE ruff:worker:1 request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter 2025-02-26 11:35:27.838205000 DEBUG ruff:worker:1 request{id=1 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/test.py ``` --- Cargo.lock | 1 + crates/ruff_server/Cargo.toml | 2 +- crates/ruff_server/src/logging.rs | 9 ++++++--- 3 files changed, 8 insertions(+), 4 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 2ab1244d41..0cefc9eee3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3990,6 +3990,7 @@ version = "0.3.19" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008" dependencies = [ + "chrono", "matchers", "nu-ansi-term 0.46.0", "once_cell", diff --git a/crates/ruff_server/Cargo.toml b/crates/ruff_server/Cargo.toml index 7924b988be..a3d0b7cee5 100644 --- a/crates/ruff_server/Cargo.toml +++ b/crates/ruff_server/Cargo.toml @@ -40,7 +40,7 @@ shellexpand = { workspace = true } thiserror = { workspace = true } toml = { workspace = true } tracing = { workspace = true } -tracing-subscriber = { workspace = true } +tracing-subscriber = { workspace = true, features = ["chrono"] } [dev-dependencies] insta = { workspace = true } diff --git a/crates/ruff_server/src/logging.rs b/crates/ruff_server/src/logging.rs index 1b23bff3bd..d4747cadae 100644 --- a/crates/ruff_server/src/logging.rs +++ b/crates/ruff_server/src/logging.rs @@ -9,7 +9,7 @@ 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}, + fmt::{format::FmtSpan, time::ChronoLocal, writer::BoxMakeWriter}, layer::SubscriberExt, Layer, }; @@ -49,10 +49,13 @@ pub(crate) fn init_logging(log_level: LogLevel, log_file: Option<&std::path::Pat Some(file) => BoxMakeWriter::new(Arc::new(file)), None => BoxMakeWriter::new(std::io::stderr), }; + + let is_trace_level = log_level == LogLevel::Trace; let subscriber = tracing_subscriber::Registry::default().with( tracing_subscriber::fmt::layer() - .with_timer(Uptime::default()) - .with_thread_names(true) + .with_timer(ChronoLocal::new("%Y-%m-%d %H:%M:%S.%f".to_string())) + .with_thread_names(is_trace_level) + .with_target(is_trace_level) .with_ansi(false) .with_writer(logger) .with_span_events(FmtSpan::ENTER)