From eb9756ce5e01677ce8001e381b00153897806a9a Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Thu, 9 Jan 2025 15:21:19 -0500 Subject: [PATCH 1/2] Support dynamic updates of the log level --- crates/lsp/src/config.rs | 19 +++++ crates/lsp/src/handlers.rs | 6 ++ crates/lsp/src/handlers_state.rs | 93 +++++++++++++++++++---- crates/lsp/src/logging.rs | 125 ++++++++++++++++++++++++------- crates/lsp/src/main_loop.rs | 21 ++++-- 5 files changed, 218 insertions(+), 46 deletions(-) diff --git a/crates/lsp/src/config.rs b/crates/lsp/src/config.rs index 3c2fa069..ff6341bf 100644 --- a/crates/lsp/src/config.rs +++ b/crates/lsp/src/config.rs @@ -9,6 +9,8 @@ use serde::Deserialize; use serde::Serialize; use struct_field_names_as_array::FieldNamesAsArray; +use crate::logging::LogLevel; + /// Configuration of the LSP #[derive(Clone, Debug, Default)] pub(crate) struct LspConfig {} @@ -55,6 +57,13 @@ pub(crate) struct VscDiagnosticsConfig { pub enable: bool, } +#[derive(Deserialize, FieldNamesAsArray, Clone, Debug)] +pub(crate) struct VscLogConfig { + // DEV NOTE: Update `section_from_key()` method after adding a field + pub log_level: Option, + pub dependency_log_levels: Option, +} + #[derive(Serialize, Deserialize, Clone, Debug)] #[serde(untagged)] pub(crate) enum VscIndentSize { @@ -127,3 +136,13 @@ pub(crate) fn indent_style_from_lsp(insert_spaces: bool) -> IndentStyle { IndentStyle::Tab } } + +impl VscLogConfig { + pub(crate) fn section_from_key(key: &str) -> &str { + match key { + "log_level" => "air.logLevel", + "dependency_log_levels" => "air.dependencyLogLevels", + _ => "unknown", // To be caught via downstream errors + } + } +} diff --git a/crates/lsp/src/handlers.rs b/crates/lsp/src/handlers.rs index e74c204f..87fbd9af 100644 --- a/crates/lsp/src/handlers.rs +++ b/crates/lsp/src/handlers.rs @@ -14,6 +14,7 @@ use tracing::Instrument; use crate::config::VscDiagnosticsConfig; use crate::config::VscDocumentConfig; +use crate::config::VscLogConfig; use crate::main_loop::LspState; // Handlers that do not mutate the world state. They take a sharing reference or @@ -46,9 +47,14 @@ pub(crate) async fn handle_initialized( VscDiagnosticsConfig::FIELD_NAMES_AS_ARRAY.to_vec(), VscDiagnosticsConfig::section_from_key, ); + let mut config_log_registrations: Vec = collect_regs( + VscLogConfig::FIELD_NAMES_AS_ARRAY.to_vec(), + VscLogConfig::section_from_key, + ); registrations.append(&mut config_document_registrations); registrations.append(&mut config_diagnostics_registrations); + registrations.append(&mut config_log_registrations); } if lsp_state diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index 2116cbe2..0bd80a50 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -5,7 +5,10 @@ // // +use std::array::IntoIter; + use anyhow::anyhow; +use anyhow::Context; use biome_lsp_converters::PositionEncoding; use biome_lsp_converters::WideEncoding; use serde_json::Value; @@ -36,6 +39,7 @@ use crate::config::indent_style_from_lsp; use crate::config::DocumentConfig; use crate::config::VscDiagnosticsConfig; use crate::config::VscDocumentConfig; +use crate::config::VscLogConfig; use crate::documents::Document; use crate::logging; use crate::logging::LogMessageSender; @@ -78,12 +82,12 @@ pub(crate) fn initialize( InitializationOptions::from_value, ); - logging::init_logging( + lsp_state.log_state = Some(logging::init_logging( log_tx, log_level, dependency_log_levels, params.client_info.as_ref(), - ); + )); // Initialize the workspace settings resolver using the initial set of client provided `workspace_folders` lsp_state.workspace_settings_resolver = WorkspaceSettingsResolver::from_workspace_folders( @@ -182,13 +186,15 @@ pub(crate) fn did_close( pub(crate) async fn did_change_configuration( _params: DidChangeConfigurationParams, client: &tower_lsp::Client, + lsp_state: &mut LspState, state: &mut WorldState, ) -> anyhow::Result<()> { - // The notification params sometimes contain data but it seems in practice - // we should just ignore it. Instead we need to pull the settings again for - // all URI of interest. + // The LSP deprecated usage of `DidChangeConfigurationParams`, but still allows + // servers to use the notification itself as a way to get notified that some + // configuration that we watch has changed. When we detect any changes, we re-pull + // everything we are interested in. - update_config(workspace_uris(state), client, state) + update_config(workspace_uris(state), client, lsp_state, state) .instrument(tracing::info_span!("did_change_configuration")) .await } @@ -252,6 +258,7 @@ pub(crate) fn did_change_formatting_options( async fn update_config( uris: Vec, client: &tower_lsp::Client, + lsp_state: &mut LspState, state: &mut WorldState, ) -> anyhow::Result<()> { let mut items: Vec = vec![]; @@ -278,15 +285,26 @@ async fn update_config( .collect(); items.append(&mut document_items); + let log_keys = VscLogConfig::FIELD_NAMES_AS_ARRAY; + let mut log_items: Vec = log_keys + .iter() + .map(|key| ConfigurationItem { + scope_uri: None, + section: Some(VscLogConfig::section_from_key(key).into()), + }) + .collect(); + items.append(&mut log_items); + let configs = client.configuration(items).await?; // We got the config items in a flat vector that's guaranteed to be // ordered in the same way it was sent in. Be defensive and check that // we've got the expected number of items before we process them chunk // by chunk - let n_document_items = document_keys.len(); let n_diagnostics_items = diagnostics_keys.len(); - let n_items = n_diagnostics_items + (n_document_items * uris.len()); + let n_document_items = document_keys.len() * uris.len(); + let n_log_items = log_keys.len(); + let n_items = n_diagnostics_items + n_document_items + n_log_items; if configs.len() != n_items { return Err(anyhow!( @@ -300,8 +318,26 @@ async fn update_config( // --- Diagnostics let keys = diagnostics_keys.into_iter(); - let items: Vec = configs.by_ref().take(n_diagnostics_items).collect(); + let items = configs.by_ref().take(n_diagnostics_items); + update_diagnostics_config(keys, items)?; + // --- Documents + let keys = document_keys.into_iter(); + let items = configs.by_ref().take(n_document_items); + update_documents_config(keys, items, uris, state)?; + + // --- Logs + let keys = log_keys.into_iter(); + let items = configs.by_ref().take(n_log_items); + update_log_config(keys, items, lsp_state)?; + + Ok(()) +} + +fn update_diagnostics_config( + keys: IntoIter<&str, 1>, + items: impl Iterator, +) -> anyhow::Result<()> { // Create a new `serde_json::Value::Object` manually to convert it // to a `VscDocumentConfig` with `from_value()`. This way serde_json // can type-check the dynamic JSON value we got from the client. @@ -321,14 +357,22 @@ async fn update_config( // lsp::spawn_diagnostics_refresh_all(state.clone()); // } - // --- Documents + Ok(()) +} + +fn update_documents_config( + keys: IntoIter<&str, 3>, + mut items: impl Iterator, + uris: Vec, + state: &mut WorldState, +) -> anyhow::Result<()> { // For each document, deserialise the vector of JSON values into a typed config for uri in uris { - let keys = document_keys.into_iter(); - let items: Vec = configs.by_ref().take(n_document_items).collect(); + let uri_keys = keys.clone(); + let uri_items = items.by_ref().take(keys.len()); let mut map = serde_json::Map::new(); - std::iter::zip(keys, items).for_each(|(key, item)| { + std::iter::zip(uri_keys, uri_items).for_each(|(key, item)| { map.insert(key.into(), item); }); @@ -344,3 +388,26 @@ async fn update_config( Ok(()) } + +fn update_log_config( + keys: IntoIter<&str, 2>, + items: impl Iterator, + lsp_state: &mut LspState, +) -> anyhow::Result<()> { + let log_state = lsp_state.log_state.as_mut().context("Missing log state")?; + + let mut map = serde_json::Map::new(); + std::iter::zip(keys, items).for_each(|(key, item)| { + map.insert(key.into(), item); + }); + + // Deserialise the VS Code configuration + let VscLogConfig { + log_level, + dependency_log_levels, + } = serde_json::from_value(serde_json::Value::Object(map))?; + + log_state.reload(log_level, dependency_log_levels); + + Ok(()) +} diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index 5a78c507..70b34df5 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -15,9 +15,15 @@ //! //! - The environment variable `AIR_LOG_LEVEL` is consulted. //! -//! - The LSP `InitializeParams.initializationOptions.logLevel` option is consulted. This -//! can be set in VS Code / Positron using `air.logLevel`, or in Zed by supplying -//! `initialization_options`. +//! - The configuration variable `air.logLevel` is consulted. This can be set in two ways: +//! +//! - As an initialization option, i.e. `InitializeParams.initializationOptions.logLevel`, +//! which is passed in on startup. In VS Code / Positron our extension preemptively +//! looks for the global `air.logLevel` configuration option and passes it through. +//! In Zed you'd set this in `initialization_options`. +//! +//! - As a dynamic global configuration option. We watch for `air.logLevel` configuration +//! changes and update the log level accordingly. //! //! - If neither are supplied, we fallback to `"info"`. //! @@ -30,9 +36,8 @@ //! //! - The environment variable `AIR_DEPENDENCY_LOG_LEVELS` is consulted. //! -//! - The LSP `InitializeParams.initializationOptions.dependencyLogLevels` option is -//! consulted. This can be set in VS Code / Positron using `air.dependencyLogLevel`, or -//! in Zed by supplying `initialization_options`. +//! - The configuration variable `air.dependencyLogLevels` is consulted. It can be set in +//! the same ways as `air.logLevel` above. //! //! - If neither are supplied, we fallback to no logging for dependency crates. //! @@ -53,19 +58,14 @@ use tower_lsp::Client; use tracing_subscriber::filter; use tracing_subscriber::fmt::time::LocalTime; use tracing_subscriber::fmt::TestWriter; +use tracing_subscriber::reload; use tracing_subscriber::{ fmt::{writer::BoxMakeWriter, MakeWriter}, layer::SubscriberExt, - Layer, }; use crate::crates; -// TODO: -// - Add `air.logLevel` and `air.dependencyLogLevels` as VS Code extension options that set -// the log levels, and pass them through the arbitrary `initializationOptions` field of -// `InitializeParams`. - const AIR_LOG_LEVEL: &str = "AIR_LOG_LEVEL"; const AIR_DEPENDENCY_LOG_LEVELS: &str = "AIR_DEPENDENCY_LOG_LEVELS"; @@ -76,15 +76,15 @@ pub(crate) struct LogMessage { pub(crate) type LogMessageSender = tokio::sync::mpsc::UnboundedSender; pub(crate) type LogMessageReceiver = tokio::sync::mpsc::UnboundedReceiver; -pub(crate) struct LogState { +pub(crate) struct LogThreadState { client: Client, log_rx: LogMessageReceiver, } // Needed for spawning the loop -unsafe impl Sync for LogState {} +unsafe impl Sync for LogThreadState {} -impl LogState { +impl LogThreadState { pub(crate) fn new(client: Client) -> (Self, LogMessageSender) { let (log_tx, log_rx) = unbounded_channel::(); let state = Self { client, log_rx }; @@ -157,14 +157,67 @@ impl<'a> MakeWriter<'a> for LogWriterMaker { } } +pub(crate) type LogReloadHandle = tracing_subscriber::reload::Handle< + tracing_subscriber::filter::Targets, + tracing_subscriber::Registry, +>; + +/// Log state managed by the LSP +/// +/// This state allows for dynamically updating the log level at runtime using [`reload`]. +/// +/// It works using an `RwLock` that's only ever locked by us inside `self.handle.reload()`, +/// this seems to be fast enough even though atomics are checked at every log call site. +/// Notably we only lock if the new log levels are actually different, which is important +/// since we call [`reload`] when ANY configuration changes. +pub(crate) struct LogState { + handle: LogReloadHandle, + + /// The log level as provided by the client, before any extra processing is done. + /// Used to check if an update is required. + log_level: Option, + + /// The dependency log levels as provided by the client, before any extra processing is done + /// Used to check if an update is required. + dependency_log_levels: Option, +} + +impl LogState { + pub(crate) fn reload( + &mut self, + log_level: Option, + dependency_log_levels: Option, + ) { + if (self.log_level == log_level) && (self.dependency_log_levels == dependency_log_levels) { + // Nothing changed + return; + } + + let (filter, message) = log_filter(log_level, dependency_log_levels.clone()); + + match self.handle.reload(filter) { + Ok(()) => { + // Update to match the new filter + tracing::info!("{message}"); + self.log_level = log_level; + self.dependency_log_levels = dependency_log_levels; + } + Err(error) => { + // Log and return without updating our internal log level + tracing::error!("Failed to update log level: {error}"); + } + } + } +} + pub(crate) fn init_logging( log_tx: LogMessageSender, log_level: Option, dependency_log_levels: Option, client_info: Option<&ClientInfo>, -) { - let log_level = resolve_log_level(log_level); - let dependency_log_levels = resolve_dependency_log_levels(dependency_log_levels); +) -> LogState { + let (filter, message) = log_filter(log_level, dependency_log_levels.clone()); + let (filter_layer, handle) = reload::Layer::new(filter); let writer = if client_info.is_some_and(|client_info| { client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") @@ -179,7 +232,7 @@ pub(crate) fn init_logging( BoxMakeWriter::new(std::io::stderr) }; - let layer = tracing_subscriber::fmt::layer() + let writer_layer = tracing_subscriber::fmt::layer() // Spend the effort cleaning up the logs before writing them. // Particularly useful for instrumented logs with spans. .pretty() @@ -199,15 +252,23 @@ pub(crate) fn init_logging( .with_timer(LocalTime::rfc_3339()) // Display the log level .with_level(true) - .with_writer(writer) - .with_filter(log_filter(log_level, dependency_log_levels)); + .with_writer(writer); - let subscriber = tracing_subscriber::Registry::default().with(layer); + let subscriber = tracing_subscriber::Registry::default() + .with(filter_layer) + .with(writer_layer); tracing::subscriber::set_global_default(subscriber) .expect("Should be able to set the global subscriber exactly once."); - tracing::info!("Logging initialized with level: {log_level}"); + // Emit message after subscriber is set up, so we actually see it + tracing::info!("{message}"); + + LogState { + handle, + log_level, + dependency_log_levels, + } } /// We use a special `TestWriter` during tests to be compatible with `cargo test`'s @@ -220,7 +281,21 @@ fn is_test_client(client_info: Option<&ClientInfo>) -> bool { client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } -fn log_filter(log_level: LogLevel, dependency_log_levels: Option) -> filter::Targets { +fn log_filter( + log_level: Option, + dependency_log_levels: Option, +) -> (filter::Targets, String) { + let log_level = resolve_log_level(log_level); + let dependency_log_levels = resolve_dependency_log_levels(dependency_log_levels); + + // Create the update message with resolved levels, it will get logged at the + // appropriate time by the caller + let message = format!( + "Updating log level: +Log level: {log_level} +Dependency log levels: {dependency_log_levels:?}" + ); + // Initialize `filter` from dependency log levels. // If nothing is supplied, dependency logs are completely off. let mut filter = match dependency_log_levels { @@ -238,7 +313,7 @@ fn log_filter(log_level: LogLevel, dependency_log_levels: Option) -> fil filter = filter.with_target(*target, log_level); } - filter + (filter, message) } fn resolve_log_level(log_level: Option) -> LogLevel { diff --git a/crates/lsp/src/main_loop.rs b/crates/lsp/src/main_loop.rs index 7dfad4de..95a61241 100644 --- a/crates/lsp/src/main_loop.rs +++ b/crates/lsp/src/main_loop.rs @@ -26,8 +26,9 @@ use crate::handlers_ext; use crate::handlers_format; use crate::handlers_state; use crate::handlers_state::ConsoleInputs; +use crate::logging; use crate::logging::LogMessageSender; -use crate::logging::LogState; +use crate::logging::LogThreadState; use crate::state::WorldState; use crate::tower_lsp::LspMessage; use crate::tower_lsp::LspNotification; @@ -145,7 +146,7 @@ pub(crate) struct GlobalState { /// Log state that gets moved to the log thread, /// and a channel for communicating with that thread which we /// pass on to `init_logging()` during `initialize()`. - log_state: Option, + log_thread_state: Option, log_tx: Option, } @@ -165,6 +166,9 @@ pub(crate) struct LspState { /// List of client capabilities that we care about pub(crate) capabilities: ResolvedClientCapabilities, + + /// State used to dynamically update the log level + pub(crate) log_state: Option, } impl Default for LspState { @@ -175,6 +179,7 @@ impl Default for LspState { position_encoding: PositionEncoding::Wide(WideEncoding::Utf16), parsers: Default::default(), capabilities: ResolvedClientCapabilities::default(), + log_state: None, } } } @@ -232,7 +237,7 @@ impl GlobalState { // tower-lsp backend and the Jupyter kernel. let (events_tx, events_rx) = tokio_unbounded_channel::(); - let (log_state, log_tx) = LogState::new(client.clone()); + let (log_thread_state, log_tx) = LogThreadState::new(client.clone()); let (auxiliary_state, auxiliary_event_tx) = AuxiliaryState::new(client.clone()); let state = Self { @@ -242,7 +247,7 @@ impl GlobalState { events_rx, auxiliary_state: Some(auxiliary_state), auxiliary_event_tx, - log_state: Some(log_state), + log_thread_state: Some(log_thread_state), log_tx: Some(log_tx), }; @@ -270,10 +275,10 @@ impl GlobalState { // Spawn latency-sensitive auxiliary and log threads. let mut set = tokio::task::JoinSet::<()>::new(); - // Take ownership over `log_state` and start the log thread. + // Take ownership over `log_thread_state` and start the log thread. // Unwrap: `start()` should only be called once. - let log_state = self.log_state.take().unwrap(); - set.spawn(async move { log_state.start().await }); + let log_thread_state = self.log_thread_state.take().unwrap(); + set.spawn(async move { log_thread_state.start().await }); // Take ownership over `auxiliary_state` and start the auxiliary thread. // Unwrap: `start()` should only be called once. @@ -326,7 +331,7 @@ impl GlobalState { handlers_state::did_change_workspace_folders(params, &mut self.lsp_state)?; }, LspNotification::DidChangeConfiguration(params) => { - handlers_state::did_change_configuration(params, &self.client, &mut self.world).await?; + handlers_state::did_change_configuration(params, &self.client, &mut self.lsp_state, &mut self.world).await?; }, LspNotification::DidChangeWatchedFiles(params) => { handlers_state::did_change_watched_files(params, &mut self.lsp_state)?; From 3d548927cce927a3e98779f1d39430621cf41f34 Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Thu, 9 Jan 2025 15:26:09 -0500 Subject: [PATCH 2/2] Remove notes about requiring a restart --- editors/code/package.json | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/editors/code/package.json b/editors/code/package.json index 582b5e17..877d15a1 100644 --- a/editors/code/package.json +++ b/editors/code/package.json @@ -39,7 +39,7 @@ "properties": { "air.logLevel": { "default": null, - "markdownDescription": "Controls the log level of the language server.\n\n**This setting requires a restart to take effect.**", + "markdownDescription": "Controls the log level of the language server.", "enum": [ "error", "warning", @@ -52,7 +52,7 @@ }, "air.dependencyLogLevels": { "default": null, - "markdownDescription": "Controls the log level of the Rust crates that the language server depends on.\n\n**This setting requires a restart to take effect.**", + "markdownDescription": "Controls the log level of the Rust crates that the language server depends on.", "scope": "application", "type": "string" }