diff --git a/.github/workflows/test-linux.yml b/.github/workflows/test-linux.yml index 9a8e0fcd..2e084756 100644 --- a/.github/workflows/test-linux.yml +++ b/.github/workflows/test-linux.yml @@ -52,7 +52,7 @@ jobs: - name: Run unit tests env: - AIR_LOG: trace + AIR_LOG_LEVEL: trace # `--nocapture` to see our own `tracing` logs # `--test-threads 1` to ensure `tracing` logs aren't interleaved run: cargo test -- --nocapture --test-threads 1 diff --git a/.github/workflows/test-mac.yml b/.github/workflows/test-mac.yml index e59db708..dbe44a94 100644 --- a/.github/workflows/test-mac.yml +++ b/.github/workflows/test-mac.yml @@ -30,7 +30,7 @@ jobs: - name: Run unit tests env: - AIR_LOG: trace + AIR_LOG_LEVEL: trace # `--nocapture` to see our own `tracing` logs # `--test-threads 1` to ensure `tracing` logs aren't interleaved run: cargo test -- --nocapture --test-threads 1 diff --git a/.github/workflows/test-windows.yml b/.github/workflows/test-windows.yml index a1b2edfb..fa95a5b2 100644 --- a/.github/workflows/test-windows.yml +++ b/.github/workflows/test-windows.yml @@ -30,7 +30,7 @@ jobs: - name: Run unit tests env: - AIR_LOG: trace + AIR_LOG_LEVEL: trace # `--nocapture` to see our own `tracing` logs # `--test-threads 1` to ensure `tracing` logs aren't interleaved run: cargo test -- --nocapture --test-threads 1 diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index 22bc0755..211eb1b2 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -65,10 +65,16 @@ pub(crate) fn initialize( state: &mut WorldState, log_tx: LogMessageSender, ) -> anyhow::Result { - // TODO: Get user specified log level from `params.initialization_options` + // TODO: Get user specified options from `params.initialization_options` let log_level = None; - - logging::init_logging(log_tx, log_level, params.client_info.as_ref()); + let dependency_log_levels = None; + + logging::init_logging( + log_tx, + log_level, + dependency_log_levels, + params.client_info.as_ref(), + ); // Defaults to UTF-16 let mut position_encoding = None; diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index 2c4bbf6f..6a6c491e 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -6,14 +6,37 @@ //! The logging system for `air lsp`. //! -//! Logs are controlled by the `air.logLevel` setting in VS Code, -//! passed through `InitializeParams` in the arbitrary `initializationOptions` field. +//! ## Air crate logs //! -//! Logs are also controlled by the `AIR_LOG` environment variable. This is preferred -//! over the extension setting, but it is unlikely to see them both be used together. -//! This can be used by other LSP clients if there is no easy way to set `initializationOptions`. +//! For air crates, a single log level is supplied as one of: error, warn, info, debug, +//! or trace, which is applied to all air crates that log. //! -//! By default, we fallback to `"info"`. +//! Resolution strategy: +//! +//! - 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`. +//! +//! - If neither are supplied, we fallback to `"info"`. +//! +//! ## Dependency crate logs +//! +//! For dependency crates, either a single log level can be supplied, or comma separated +//! `target=level` pairs can be supplied, like `tower_lsp=debug,tokio=info`. +//! +//! Resolution strategy: +//! +//! - 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`. +//! +//! - If neither are supplied, we fallback to no logging for dependency crates. +//! +//! ## IDE support //! //! For VS Code and Zed, which are known to support `window/logMessage` well, logging will //! emit a `window/logMessage` message. Otherwise, logging will write to `stderr`, @@ -22,11 +45,12 @@ use core::str; use serde::Deserialize; use std::fmt::Display; use std::io::{Error as IoError, ErrorKind, Write}; +use std::str::FromStr; use tokio::sync::mpsc::unbounded_channel; use tower_lsp::lsp_types::ClientInfo; use tower_lsp::lsp_types::MessageType; use tower_lsp::Client; -use tracing::level_filters::LevelFilter; +use tracing_subscriber::filter; use tracing_subscriber::fmt::time::LocalTime; use tracing_subscriber::fmt::TestWriter; use tracing_subscriber::{ @@ -36,10 +60,12 @@ use tracing_subscriber::{ }; // TODO: -// - Add `air.logLevel` as a VS Code extension option that sets the log level, -// and pass it through the arbitrary `initializationOptions` field of `InitializeParams`. +// - 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 LOG_ENV_KEY: &str = "AIR_LOG"; +const AIR_LOG_LEVEL: &str = "AIR_LOG_LEVEL"; +const AIR_DEPENDENCY_LOG_LEVELS: &str = "AIR_DEPENDENCY_LOG_LEVELS"; pub(crate) struct LogMessage { contents: String, @@ -132,9 +158,11 @@ impl<'a> MakeWriter<'a> for LogWriterMaker { 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); let writer = if client_info.is_some_and(|client_info| { client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") @@ -167,7 +195,7 @@ pub(crate) fn init_logging( // Display the log level .with_level(true) .with_writer(writer) - .with_filter(LogLevelFilter { filter: log_level }); + .with_filter(log_filter(log_level, dependency_log_levels)); let subscriber = tracing_subscriber::Registry::default().with(layer); @@ -195,9 +223,41 @@ fn is_test_client(client_info: Option<&ClientInfo>) -> bool { client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } +// TODO: Is there a way to generate this at compile time? +const TARGETS: &[&str] = &[ + "air_r_factory", + "air_r_formatter", + "air_r_parser", + "air_r_syntax", + "fs", + "line_ending", + "lsp", +]; + +fn log_filter(log_level: LogLevel, dependency_log_levels: Option) -> filter::Targets { + // Initialize `filter` from dependency log levels. + // If nothing is supplied, dependency logs are completely off. + let mut filter = match dependency_log_levels { + Some(dependency_log_levels) => match filter::Targets::from_str(&dependency_log_levels) { + Ok(level) => level, + Err(_) => filter::Targets::new(), + }, + None => filter::Targets::new(), + }; + + let log_level = log_level.tracing_level(); + + // Apply the air log level to each air crate that logs + for target in TARGETS { + filter = filter.with_target(*target, log_level); + } + + filter +} + fn resolve_log_level(log_level: Option) -> LogLevel { // Check log environment variable, this overrides any Client options - if let Some(log_level) = std::env::var(LOG_ENV_KEY) + if let Some(log_level) = std::env::var(AIR_LOG_LEVEL) .ok() .and_then(|level| serde_json::from_value(serde_json::Value::String(level)).ok()) { @@ -209,8 +269,23 @@ fn resolve_log_level(log_level: Option) -> LogLevel { return log_level; } - // Fallback - LogLevel::default() + // Default to info logs for air crates + LogLevel::Info +} + +fn resolve_dependency_log_levels(dependency_log_levels: Option) -> Option { + // Check dependency log environment variable, this overrides any Client options + if let Ok(dependency_log_levels) = std::env::var(AIR_DEPENDENCY_LOG_LEVELS) { + return Some(dependency_log_levels); + } + + // Client specified log level through initialization parameters + if dependency_log_levels.is_some() { + return dependency_log_levels; + } + + // Default to no logs for dependency crates + None } #[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)] @@ -247,30 +322,3 @@ impl Display for LogLevel { } } } - -/// Filters out logs which have a log level lower than the level 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 { - // This is a potential reason to use `air_` as the crate prefix, - // it would make it easy to set the `tracing_level()` for only air related crates - let filter = if meta.target().starts_with("air") || meta.target().starts_with("lsp") { - self.filter.tracing_level() - } else { - tracing::Level::WARN - }; - - meta.level() <= &filter - } - - fn max_level_hint(&self) -> Option { - Some(LevelFilter::from_level(self.filter.tracing_level())) - } -} diff --git a/crates/lsp_test/src/tower_lsp/codec.rs b/crates/lsp_test/src/tower_lsp/codec.rs index 5c1068c2..38f2af83 100644 --- a/crates/lsp_test/src/tower_lsp/codec.rs +++ b/crates/lsp_test/src/tower_lsp/codec.rs @@ -17,7 +17,7 @@ use bytes::buf::BufMut; use bytes::{Buf, BytesMut}; use memchr::memmem; use serde::{de::DeserializeOwned, Serialize}; -use tracing::{trace, warn}; +use tracing::warn; use tokio_util::codec::{Decoder, Encoder}; @@ -120,7 +120,7 @@ impl Encoder for LanguageServerCodec { fn encode(&mut self, item: T, dst: &mut BytesMut) -> Result<(), Self::Error> { let msg = serde_json::to_string(&item)?; - trace!("-> {}", msg); + // trace!("-> {}", msg); // Reserve just enough space to hold the `Content-Length: ` and `\r\n\r\n` constants, // the length of the message, and the message body. @@ -160,7 +160,7 @@ impl Decoder for LanguageServerCodec { let result = if message.is_empty() { Ok(None) } else { - trace!("<- {}", message); + // trace!("<- {}", message); match serde_json::from_str(message) { Ok(parsed) => Ok(Some(parsed)), Err(err) => Err(err.into()),