diff --git a/Cargo.lock b/Cargo.lock index 10223e5bef..e7c3133ada 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -10604,6 +10604,7 @@ dependencies = [ "util", "which 6.0.3", "worktree", + "zlog", ] [[package]] @@ -17465,6 +17466,7 @@ dependencies = [ "workspace", "zed_actions", "zeta", + "zlog_settings", ] [[package]] @@ -17772,6 +17774,25 @@ dependencies = [ "zstd", ] +[[package]] +name = "zlog" +version = "0.1.0" +dependencies = [ + "log", +] + +[[package]] +name = "zlog_settings" +version = "0.1.0" +dependencies = [ + "anyhow", + "gpui", + "schemars", + "serde", + "settings", + "zlog", +] + [[package]] name = "zstd" version = "0.11.2+zstd.1.5.2" diff --git a/Cargo.toml b/Cargo.toml index aff7e9d852..3f68f8121d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -171,6 +171,8 @@ members = [ "crates/zed", "crates/zed_actions", "crates/zeta", + "crates/zlog", + "crates/zlog_settings", # # Extensions @@ -374,6 +376,8 @@ worktree = { path = "crates/worktree" } zed = { path = "crates/zed" } zed_actions = { path = "crates/zed_actions" } zeta = { path = "crates/zeta" } +zlog = { path = "crates/zlog" } +zlog_settings = { path = "crates/zlog_settings" } # # External crates diff --git a/crates/project/Cargo.toml b/crates/project/Cargo.toml index fb86ff5f3c..429a982ca9 100644 --- a/crates/project/Cargo.toml +++ b/crates/project/Cargo.toml @@ -83,6 +83,7 @@ url.workspace = true util.workspace = true which.workspace = true worktree.workspace = true +zlog.workspace = true [dev-dependencies] client = { workspace = true, features = ["test-support"] } diff --git a/crates/project/src/lsp_store.rs b/crates/project/src/lsp_store.rs index 68ebf94347..2954dd3570 100644 --- a/crates/project/src/lsp_store.rs +++ b/crates/project/src/lsp_store.rs @@ -1142,6 +1142,7 @@ impl LocalLspStore { mut buffers: Vec, push_to_history: bool, trigger: FormatTrigger, + logger: zlog::Logger, cx: &mut AsyncApp, ) -> anyhow::Result { // Do not allow multiple concurrent formatting requests for the @@ -1201,6 +1202,7 @@ impl LocalLspStore { // handle whitespace formatting { if settings.remove_trailing_whitespace_on_save { + zlog::trace!(logger => "removing trailing whitespace"); let diff = buffer .handle .read_with(cx, |buffer, cx| buffer.remove_trailing_whitespace(cx))? @@ -1217,6 +1219,7 @@ impl LocalLspStore { } if settings.ensure_final_newline_on_save { + zlog::trace!(logger => "ensuring final newline"); buffer.handle.update(cx, |buffer, cx| { buffer.start_transaction(); buffer.ensure_final_newline(cx); @@ -1243,6 +1246,7 @@ impl LocalLspStore { if should_run_code_actions_on_format { if have_code_actions_to_run_on_format { + zlog::trace!(logger => "going to run code actions on format"); break 'ca_formatter Some(Formatter::CodeActions( settings.code_actions_on_format.clone(), )); @@ -1258,8 +1262,10 @@ impl LocalLspStore { match &settings.formatter { SelectedFormatter::Auto => { if settings.prettier.allowed { + zlog::trace!(logger => "Formatter set to auto: defaulting to prettier"); std::slice::from_ref(&Formatter::Prettier) } else { + zlog::trace!(logger => "Formatter set to auto: defaulting to primary language server"); std::slice::from_ref(&Formatter::LanguageServer { name: None }) } } @@ -1307,6 +1313,10 @@ impl LocalLspStore { 'formatters: for formatter in formatters { match formatter { Formatter::Prettier => { + let logger = zlog::scoped!(logger => "prettier"); + zlog::trace!(logger => "formatting"); + let _timer = zlog::time!(logger => "Formatting buffer via prettier"); + let prettier = lsp_store.read_with(cx, |lsp_store, _cx| { lsp_store.prettier_store().unwrap().downgrade() })?; @@ -1316,17 +1326,21 @@ impl LocalLspStore { .transpose(); let Ok(diff) = diff_result else { result = Err(diff_result.unwrap_err()); + zlog::error!(logger => "failed, reason: {:?}", result.as_ref()); break 'formatters; }; let Some(diff) = diff else { + zlog::trace!(logger => "No changes"); continue 'formatters; }; if let Some(err) = err_if_buffer_edited_since_start(buffer, transaction_id_format, &cx) { + zlog::warn!(logger => "Buffer edited while formatting. Aborting"); result = Err(err); break 'formatters; } + zlog::trace!(logger => "Applying changes"); buffer.handle.update(cx, |buffer, cx| { buffer.start_transaction(); buffer.apply_diff(diff, cx); @@ -1338,6 +1352,11 @@ impl LocalLspStore { })?; } Formatter::External { command, arguments } => { + let logger = zlog::scoped!(logger => "command"); + zlog::trace!(logger => "formatting"); + let _timer = + zlog::time!(logger => "Formatting buffer via external command"); + let diff_result = Self::format_via_external_command( buffer, command.as_ref(), @@ -1350,17 +1369,21 @@ impl LocalLspStore { }); let Ok(diff) = diff_result else { result = Err(diff_result.unwrap_err()); + zlog::error!(logger => "failed, reason: {:?}", result.as_ref()); break 'formatters; }; let Some(diff) = diff else { + zlog::trace!(logger => "No changes"); continue 'formatters; }; if let Some(err) = err_if_buffer_edited_since_start(buffer, transaction_id_format, &cx) { + zlog::warn!(logger => "Buffer edited while formatting. Aborting"); result = Err(err); break 'formatters; } + zlog::trace!(logger => "Applying changes"); buffer.handle.update(cx, |buffer, cx| { buffer.start_transaction(); buffer.apply_diff(diff, cx); @@ -1372,8 +1395,13 @@ impl LocalLspStore { })?; } Formatter::LanguageServer { name } => { + let logger = zlog::scoped!(logger => "language-server"); + zlog::trace!(logger => "formatting"); + let _timer = + zlog::time!(logger => "Formatting buffer using language server"); + let Some(buffer_path_abs) = buffer.abs_path.as_ref() else { - log::warn!("Cannot format buffer that is not backed by a file on disk using language servers. Skipping"); + zlog::warn!(logger => "Cannot format buffer that is not backed by a file on disk using language servers. Skipping"); continue 'formatters; }; @@ -1409,7 +1437,15 @@ impl LocalLspStore { } }; + zlog::trace!( + logger => + "Formatting buffer '{:?}' using language server '{:?}'", + buffer_path_abs.as_path().to_string_lossy(), + language_server.name() + ); + let edits_result = if let Some(ranges) = buffer.ranges.as_ref() { + zlog::trace!(logger => "formatting ranges"); Self::format_ranges_via_lsp( &lsp_store, &buffer.handle, @@ -1422,6 +1458,7 @@ impl LocalLspStore { .await .context("Failed to format ranges via language server") } else { + zlog::trace!(logger => "formatting full"); Self::format_via_lsp( &lsp_store, &buffer.handle, @@ -1436,19 +1473,22 @@ impl LocalLspStore { let Ok(edits) = edits_result else { result = Err(edits_result.unwrap_err()); + zlog::error!(logger => "Failed, reason: {:?}", result.as_ref()); break 'formatters; }; if edits.is_empty() { + zlog::trace!(logger => "No changes"); continue 'formatters; } if let Some(err) = err_if_buffer_edited_since_start(buffer, transaction_id_format, &cx) { + zlog::warn!(logger => "Buffer edited while formatting. Aborting"); result = Err(err); break 'formatters; } - + zlog::trace!(logger => "Applying changes"); buffer.handle.update(cx, |buffer, cx| { buffer.start_transaction(); buffer.edit(edits, None, cx); @@ -1460,8 +1500,12 @@ impl LocalLspStore { })?; } Formatter::CodeActions(code_actions) => { + let logger = zlog::scoped!(logger => "code-actions"); + zlog::trace!(logger => "formatting"); + let _timer = zlog::time!(logger => "Formatting buffer using code actions"); + let Some(buffer_path_abs) = buffer.abs_path.as_ref() else { - log::warn!("Cannot format buffer that is not backed by a file on disk using code actions. Skipping"); + zlog::warn!(logger => "Cannot format buffer that is not backed by a file on disk using code actions. Skipping"); continue 'formatters; }; let code_action_kinds = code_actions @@ -1471,6 +1515,7 @@ impl LocalLspStore { }) .collect::>(); if code_action_kinds.is_empty() { + zlog::trace!(logger => "No code action kinds enabled, skipping"); continue 'formatters; } @@ -1494,7 +1539,8 @@ impl LocalLspStore { let Ok(actions) = actions_result else { // note: it may be better to set result to the error and break formatters here // but for now we try to execute the actions that we can resolve and skip the rest - log::error!( + zlog::error!( + logger => "Failed to resolve code actions with kinds {:?} with language server {}", code_action_kinds.iter().map(|kind| kind.as_str()).join(", "), language_server.name() @@ -1507,6 +1553,7 @@ impl LocalLspStore { } if actions_and_servers.is_empty() { + zlog::trace!(logger => "No code actions were resolved, continuing"); continue 'formatters; } @@ -1525,6 +1572,8 @@ impl LocalLspStore { ) }; + zlog::trace!(logger => "Executing {}", describe_code_action(&action)); + // NOTE: code below duplicated from `Self::deserialize_workspace_edit` // but filters out and logs warnings for code actions that cause unreasonably // difficult handling on our part, such as: @@ -1542,7 +1591,8 @@ impl LocalLspStore { if let Err(err) = Self::try_resolve_code_action(server, &mut action).await { - log::error!( + zlog::error!( + logger => "Failed to resolve {}. Error: {}", describe_code_action(&action), err @@ -1550,14 +1600,16 @@ impl LocalLspStore { continue 'actions; } if let Some(_) = action.lsp_action.command() { - log::warn!( + zlog::warn!( + logger => "Code actions with commands are not supported while formatting. Skipping {}", describe_code_action(&action), ); continue 'actions; } let Some(edit) = action.lsp_action.edit().cloned() else { - log::warn!( + zlog::warn!( + logger => "No edit found for while formatting. Skipping {}", describe_code_action(&action), ); @@ -1565,6 +1617,11 @@ impl LocalLspStore { }; if edit.changes.is_none() && edit.document_changes.is_none() { + zlog::trace!( + logger => + "No changes for code action. Skipping {}", + describe_code_action(&action), + ); continue 'actions; } @@ -1591,11 +1648,20 @@ impl LocalLspStore { let mut edits = Vec::with_capacity(operations.len()); + if operations.is_empty() { + zlog::trace!( + logger => + "No changes for code action. Skipping {}", + describe_code_action(&action), + ); + continue 'actions; + } for operation in operations { let op = match operation { lsp::DocumentChangeOperation::Edit(op) => op, lsp::DocumentChangeOperation::Op(_) => { - log::warn!( + zlog::warn!( + logger => "Code actions which create, delete, or rename files are not supported on format. Skipping {}", describe_code_action(&action), ); @@ -1603,7 +1669,8 @@ impl LocalLspStore { } }; let Ok(file_path) = op.text_document.uri.to_file_path() else { - log::warn!( + zlog::warn!( + logger => "Failed to convert URI '{:?}' to file path. Skipping {}", &op.text_document.uri, describe_code_action(&action), @@ -1611,7 +1678,8 @@ impl LocalLspStore { continue 'actions; }; if &file_path != buffer_path_abs { - log::warn!( + zlog::warn!( + logger => "File path '{:?}' does not match buffer path '{:?}'. Skipping {}", file_path, buffer_path_abs, @@ -1634,7 +1702,8 @@ impl LocalLspStore { } } Edit::Snippet(_) => { - log::warn!( + zlog::warn!( + logger => "Code actions which produce snippet edits are not supported during formatting. Skipping {}", describe_code_action(&action), ); @@ -1643,35 +1712,41 @@ impl LocalLspStore { } } let edits_result = lsp_store - .update(cx, |lsp_store, cx| { - lsp_store.as_local_mut().unwrap().edits_from_lsp( - &buffer.handle, - lsp_edits, - server.server_id(), - op.text_document.version, - cx, - ) - })? - .await - .with_context( - || format!( - "Failed to resolve edits from LSP for buffer {:?} while handling {}", - buffer_path_abs.as_path(), - describe_code_action(&action), - ) - ).log_err(); - let Some(resolved_edits) = edits_result else { + .update(cx, |lsp_store, cx| { + lsp_store.as_local_mut().unwrap().edits_from_lsp( + &buffer.handle, + lsp_edits, + server.server_id(), + op.text_document.version, + cx, + ) + })? + .await; + let Ok(resolved_edits) = edits_result else { + zlog::warn!( + logger => + "Failed to resolve edits from LSP for buffer {:?} while handling {}", + buffer_path_abs.as_path(), + describe_code_action(&action), + ); continue 'actions; }; edits.extend(resolved_edits); } + if edits.is_empty() { + zlog::warn!(logger => "No edits resolved from LSP"); + continue 'actions; + } + if let Some(err) = err_if_buffer_edited_since_start(buffer, transaction_id_format, &cx) { + zlog::warn!(logger => "Buffer edited while formatting. Aborting"); result = Err(err); break 'formatters; } + zlog::info!(logger => "Applying changes"); buffer.handle.update(cx, |buffer, cx| { buffer.start_transaction(); buffer.edit(edits, None, cx); @@ -1689,6 +1764,7 @@ impl LocalLspStore { let buffer_handle = buffer.handle.clone(); buffer.handle.update(cx, |buffer, _| { let Some(transaction_id) = transaction_id_format else { + zlog::trace!(logger => "No formatting transaction id"); return result; }; let Some(transaction_id_last) = @@ -1697,9 +1773,11 @@ impl LocalLspStore { // unwrapping should work here, how would we get a transaction id // with no transaction on the undo stack? // *but* it occasionally panics. Avoiding panics for now... + zlog::warn!(logger => "No transaction present on undo stack, despite having a formatting transaction id?"); return result; }; if transaction_id_last != transaction_id { + zlog::trace!(logger => "Last transaction on undo stack is not the formatting transaction, skipping finalization & update of project transaction"); return result; } let transaction = buffer @@ -1708,6 +1786,7 @@ impl LocalLspStore { .expect("There is a transaction on the undo stack if we were able to peek it"); // debug_assert_eq!(transaction.id, transaction_id); if !push_to_history { + zlog::trace!(logger => "forgetting format transaction"); buffer.forget_transaction(transaction.id); } project_transaction @@ -1799,6 +1878,9 @@ impl LocalLspStore { settings: &LanguageSettings, cx: &mut AsyncApp, ) -> Result, Arc)>> { + let logger = zlog::scoped!("lsp_format"); + zlog::info!(logger => "Formatting via LSP"); + let uri = lsp::Url::from_file_path(abs_path) .map_err(|_| anyhow!("failed to convert abs path to uri"))?; let text_document = lsp::TextDocumentIdentifier::new(uri); @@ -1808,6 +1890,8 @@ impl LocalLspStore { let range_formatting_provider = capabilities.document_range_formatting_provider.as_ref(); let lsp_edits = if matches!(formatting_provider, Some(p) if *p != OneOf::Left(false)) { + let _timer = zlog::time!(logger => "format-full") + .warn_if_gt(std::time::Duration::from_millis(0)); language_server .request::(lsp::DocumentFormattingParams { text_document, @@ -1816,6 +1900,8 @@ impl LocalLspStore { }) .await? } else if matches!(range_formatting_provider, Some(p) if *p != OneOf::Left(false)) { + let _timer = zlog::time!(logger => "format-range") + .warn_if_gt(std::time::Duration::from_millis(0)); let buffer_start = lsp::Position::new(0, 0); let buffer_end = buffer.update(cx, |b, _| point_to_lsp(b.max_point_utf16()))?; language_server @@ -7840,7 +7926,10 @@ impl LspStore { trigger: FormatTrigger, cx: &mut Context, ) -> Task> { + let logger = zlog::scoped!("format"); if let Some(_) = self.as_local() { + zlog::trace!(logger => "Formatting locally"); + let logger = zlog::scoped!(logger => "local"); let buffers = buffers .into_iter() .map(|buffer_handle| { @@ -7879,15 +7968,22 @@ impl LspStore { ranges, }); } + zlog::trace!(logger => "Formatting {:?} buffers", formattable_buffers.len()); + let format_timer = zlog::time!(logger => "Formatting buffers"); let result = LocalLspStore::format_locally( lsp_store.clone(), formattable_buffers, push_to_history, trigger, + logger, cx, ) .await; + format_timer.end(); + + zlog::trace!(logger => "Formatting completed with result {:?}", result.as_ref().map(|_| "")); + lsp_store.update(cx, |lsp_store, _| { lsp_store.update_last_formatting_failure(&result); })?; @@ -7895,16 +7991,21 @@ impl LspStore { result }) } else if let Some((client, project_id)) = self.upstream_client() { + zlog::trace!(logger => "Formatting remotely"); + let logger = zlog::scoped!(logger => "remote"); // Don't support formatting ranges via remote match target { LspFormatTarget::Buffers => {} LspFormatTarget::Ranges(_) => { + zlog::trace!(logger => "Ignoring unsupported remote range formatting request"); return Task::ready(Ok(ProjectTransaction::default())); } } let buffer_store = self.buffer_store(); cx.spawn(async move |lsp_store, cx| { + zlog::trace!(logger => "Sending remote format request"); + let request_timer = zlog::time!(logger => "remote format request"); let result = client .request(proto::FormatBuffers { project_id, @@ -7916,12 +8017,16 @@ impl LspStore { }) .await .and_then(|result| result.transaction.context("missing transaction")); + request_timer.end(); + + zlog::trace!(logger => "Remote format request resolved to {:?}", result.as_ref().map(|_| "")); lsp_store.update(cx, |lsp_store, _| { lsp_store.update_last_formatting_failure(&result); })?; let transaction_response = result?; + let _timer = zlog::time!(logger => "deserializing project transaction"); buffer_store .update(cx, |buffer_store, cx| { buffer_store.deserialize_project_transaction( @@ -7933,6 +8038,7 @@ impl LspStore { .await }) } else { + zlog::trace!(logger => "Not formatting"); Task::ready(Ok(ProjectTransaction::default())) } } diff --git a/crates/zed/Cargo.toml b/crates/zed/Cargo.toml index 0232fabc72..c532185494 100644 --- a/crates/zed/Cargo.toml +++ b/crates/zed/Cargo.toml @@ -135,6 +135,7 @@ welcome.workspace = true workspace.workspace = true zed_actions.workspace = true zeta.workspace = true +zlog_settings.workspace = true [target.'cfg(target_os = "windows")'.dependencies] windows.workspace = true diff --git a/crates/zed/src/main.rs b/crates/zed/src/main.rs index ed2ea1d1bf..dc883f8f1f 100644 --- a/crates/zed/src/main.rs +++ b/crates/zed/src/main.rs @@ -302,6 +302,7 @@ fn main() { AppCommitSha::set_global(app_commit_sha, cx); } settings::init(cx); + zlog_settings::init(cx); handle_settings_file_changes(user_settings_file_rx, cx, handle_settings_changed); handle_keymap_file_changes(user_keymap_file_rx, cx); client::init_settings(cx); diff --git a/crates/zlog/Cargo.toml b/crates/zlog/Cargo.toml new file mode 100644 index 0000000000..9b7674d934 --- /dev/null +++ b/crates/zlog/Cargo.toml @@ -0,0 +1,18 @@ +[package] +name = "zlog" +version = "0.1.0" +edition.workspace = true +publish.workspace = true +license = "GPL-3.0-or-later" + +[lints] +workspace = true + +[lib] +path = "src/zlog.rs" + +[features] +default = [] + +[dependencies] +log.workspace = true diff --git a/crates/zlog/LICENSE-GPL b/crates/zlog/LICENSE-GPL new file mode 120000 index 0000000000..89e542f750 --- /dev/null +++ b/crates/zlog/LICENSE-GPL @@ -0,0 +1 @@ +../../LICENSE-GPL \ No newline at end of file diff --git a/crates/zlog/src/zlog.rs b/crates/zlog/src/zlog.rs new file mode 100644 index 0000000000..3fbad6f4f3 --- /dev/null +++ b/crates/zlog/src/zlog.rs @@ -0,0 +1,415 @@ +//! # logger +pub use log as log_impl; + +pub const SCOPE_DEPTH_MAX: usize = 4; + +/// because we are currently just wrapping the `log` crate in `zlog`, +/// we need to work around the fact that the `log` crate only provides a +/// single global level filter. In order to have more precise control until +/// we no longer wrap `log`, we bump up the priority of log level so that it +/// will be logged, even if the actual level is lower +/// This is fine for now, as we use a `info` level filter by default in releases, +/// which hopefully won't result in confusion like `warn` or `error` levels might. +pub fn min_printed_log_level(level: log_impl::Level) -> log_impl::Level { + // this logic is defined based on the logic used in the `log` crate, + // which checks that a logs level is <= both of these values, + // so we take the minimum of the two values to ensure that check passes + let level_min_static = log_impl::STATIC_MAX_LEVEL; + let level_min_dynamic = log_impl::max_level(); + if level <= level_min_static && level <= level_min_dynamic { + return level; + } + return log_impl::LevelFilter::min(level_min_static, level_min_dynamic) + .to_level() + .unwrap_or(level); +} + +#[macro_export] +macro_rules! log { + ($logger:expr, $level:expr, $($arg:tt)+) => { + let level = $level; + let logger = $logger; + let (enabled, level) = $crate::scope_map::is_scope_enabled(&logger.scope, level); + if enabled { + $crate::log_impl::log!(level, "[{}]: {}", &logger.fmt_scope(), format!($($arg)+)); + } + } +} + +#[macro_export] +macro_rules! trace { + ($logger:expr => $($arg:tt)+) => { + $crate::log!($logger, $crate::log_impl::Level::Trace, $($arg)+); + }; + ($($arg:tt)+) => { + $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Trace, $($arg)+); + }; +} + +#[macro_export] +macro_rules! debug { + ($logger:expr => $($arg:tt)+) => { + $crate::log!($logger, $crate::log_impl::Level::Debug, $($arg)+); + }; + ($($arg:tt)+) => { + $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Debug, $($arg)+); + }; +} + +#[macro_export] +macro_rules! info { + ($logger:expr => $($arg:tt)+) => { + $crate::log!($logger, $crate::log_impl::Level::Info, $($arg)+); + }; + ($($arg:tt)+) => { + $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Info, $($arg)+); + }; +} + +#[macro_export] +macro_rules! warn { + ($logger:expr => $($arg:tt)+) => { + $crate::log!($logger, $crate::log_impl::Level::Warn, $($arg)+); + }; + ($($arg:tt)+) => { + $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Warn, $($arg)+); + }; +} + +#[macro_export] +macro_rules! error { + ($logger:expr => $($arg:tt)+) => { + $crate::log!($logger, $crate::log_impl::Level::Error, $($arg)+); + }; + ($($arg:tt)+) => { + $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Error, $($arg)+); + }; +} + +/// Creates a timer that logs the duration it was active for either when +/// it is dropped, or when explicitly stopped using the `end` method. +/// Logs at the `trace` level. +/// Note that it will include time spent across await points +/// (i.e. should not be used to measure the performance of async code) +/// However, this is a feature not a bug, as it allows for a more accurate +/// understanding of how long the action actually took to complete, including +/// interruptions, which can help explain why something may have timed out, +/// why it took longer to complete than it would had the await points resolved +/// immediately, etc. +#[macro_export] +macro_rules! time { + ($logger:expr => $name:expr) => { + $crate::Timer::new($logger, $name) + }; + ($name:expr) => { + time!($crate::default_logger!() => $name) + }; +} + +#[macro_export] +macro_rules! scoped { + ($parent:expr => $name:expr) => {{ + let parent = $parent; + let name = $name; + let mut scope = parent.scope; + let mut index = 1; // always have crate/module name + while index < scope.len() && !scope[index].is_empty() { + index += 1; + } + if index >= scope.len() { + #[cfg(debug_assertions)] + { + panic!("Scope overflow trying to add scope {}", name); + } + #[cfg(not(debug_assertions))] + { + $crate::warn!( + parent => + "Scope overflow trying to add scope {}... ignoring scope", + name + ); + } + } + scope[index] = name; + $crate::Logger { scope } + }}; + ($name:expr) => { + $crate::scoped!($crate::default_logger!() => $name) + }; +} + +#[macro_export] +macro_rules! default_logger { + () => { + $crate::Logger { + scope: $crate::private::scope_new(&[$crate::crate_name!()]), + } + }; +} + +#[macro_export] +macro_rules! crate_name { + () => { + $crate::private::extract_crate_name_from_module_path(module_path!()) + }; +} + +/// functions that are used in macros, and therefore must be public, +/// but should not be used directly +pub mod private { + use super::*; + + pub fn extract_crate_name_from_module_path(module_path: &'static str) -> &'static str { + return module_path + .split_once("::") + .map(|(crate_name, _)| crate_name) + .unwrap_or(module_path); + } + + pub fn scope_new(scopes: &[&'static str]) -> Scope { + assert!(scopes.len() <= SCOPE_DEPTH_MAX); + let mut scope = [""; SCOPE_DEPTH_MAX]; + scope[0..scopes.len()].copy_from_slice(scopes); + scope + } + + pub fn scope_alloc_new(scopes: &[&str]) -> ScopeAlloc { + assert!(scopes.len() <= SCOPE_DEPTH_MAX); + let mut scope = [""; SCOPE_DEPTH_MAX]; + scope[0..scopes.len()].copy_from_slice(scopes); + scope.map(|s| s.to_string()) + } + + pub fn scope_to_alloc(scope: &Scope) -> ScopeAlloc { + return scope.map(|s| s.to_string()); + } +} + +pub type Scope = [&'static str; SCOPE_DEPTH_MAX]; +pub type ScopeAlloc = [String; SCOPE_DEPTH_MAX]; +const SCOPE_STRING_SEP: &'static str = "."; + +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Logger { + pub scope: Scope, +} + +impl Logger { + pub fn fmt_scope(&self) -> String { + let mut last = 0; + for s in self.scope { + if s.is_empty() { + break; + } + last += 1; + } + + return self.scope[0..last].join(SCOPE_STRING_SEP); + } +} + +pub struct Timer { + pub logger: Logger, + pub start_time: std::time::Instant, + pub name: &'static str, + pub warn_if_longer_than: Option, + pub done: bool, +} + +impl Drop for Timer { + fn drop(&mut self) { + self.finish(); + } +} + +impl Timer { + #[must_use = "Timer will stop when dropped, the result of this function should be saved in a variable prefixed with `_` if it should stop when dropped"] + pub fn new(logger: Logger, name: &'static str) -> Self { + return Self { + logger, + name, + start_time: std::time::Instant::now(), + warn_if_longer_than: None, + done: false, + }; + } + pub fn warn_if_gt(mut self, warn_limit: std::time::Duration) -> Self { + self.warn_if_longer_than = Some(warn_limit); + return self; + } + + pub fn end(mut self) { + self.finish(); + } + + fn finish(&mut self) { + if self.done { + return; + } + let elapsed = self.start_time.elapsed(); + if let Some(warn_limit) = self.warn_if_longer_than { + if elapsed > warn_limit { + crate::warn!( + self.logger => + "Timer '{}' took {:?}. Which was longer than the expected limit of {:?}", + self.name, + elapsed, + warn_limit + ); + self.done = true; + return; + } + } + crate::trace!( + self.logger => + "Timer '{}' finished in {:?}", + self.name, + elapsed + ); + self.done = true; + } +} + +pub mod scope_map { + use std::{ + collections::HashMap, + hash::{DefaultHasher, Hasher}, + sync::{ + atomic::{AtomicU64, Ordering}, + RwLock, + }, + }; + + use super::*; + + type ScopeMap = HashMap; + static SCOPE_MAP: RwLock> = RwLock::new(None); + static SCOPE_MAP_HASH: AtomicU64 = AtomicU64::new(0); + + pub fn is_scope_enabled(scope: &Scope, level: log_impl::Level) -> (bool, log_impl::Level) { + let level_min = min_printed_log_level(level); + if level <= level_min { + // [FAST PATH] + // if the message is at or below the minimum printed log level + // (where error < warn < info etc) then always enable + return (true, level); + } + + let Ok(map) = SCOPE_MAP.read() else { + // on failure, default to enabled detection done by `log` crate + return (true, level); + }; + + let Some(map) = map.as_ref() else { + // on failure, default to enabled detection done by `log` crate + return (true, level); + }; + + if map.is_empty() { + // if no scopes are enabled, default to enabled detection done by `log` crate + return (true, level); + } + let mut scope_alloc = private::scope_to_alloc(scope); + let mut level_enabled = map.get(&scope_alloc); + if level_enabled.is_none() { + for i in (0..SCOPE_DEPTH_MAX).rev() { + if scope_alloc[i] == "" { + continue; + } + scope_alloc[i].clear(); + if let Some(level) = map.get(&scope_alloc) { + level_enabled = Some(level); + break; + } + } + } + let Some(level_enabled) = level_enabled else { + // if this scope isn't configured, default to enabled detection done by `log` crate + return (true, level); + }; + if level_enabled < &level { + // if the configured level is lower than the requested level, disable logging + // note: err = 0, warn = 1, etc. + return (false, level); + } + + // note: bumping level to min level that will be printed + // to work around log crate limitations + return (true, level_min); + } + + fn hash_scope_map_settings(map: &HashMap) -> u64 { + let mut hasher = DefaultHasher::new(); + let mut items = map.iter().collect::>(); + items.sort(); + for (key, value) in items { + Hasher::write(&mut hasher, key.as_bytes()); + Hasher::write(&mut hasher, value.as_bytes()); + } + return hasher.finish(); + } + + pub fn refresh(settings: &HashMap) { + let hash_old = SCOPE_MAP_HASH.load(Ordering::Acquire); + let hash_new = hash_scope_map_settings(settings); + if hash_old == hash_new && hash_old != 0 { + return; + } + // compute new scope map then atomically swap it, instead of + // updating in place to reduce contention + let mut map_new = ScopeMap::with_capacity(settings.len()); + 'settings: for (key, value) in settings { + let level = match value.to_ascii_lowercase().as_str() { + "" => log_impl::Level::Trace, + "trace" => log_impl::Level::Trace, + "debug" => log_impl::Level::Debug, + "info" => log_impl::Level::Info, + "warn" => log_impl::Level::Warn, + "error" => log_impl::Level::Error, + "off" | "disable" | "no" | "none" | "disabled" => { + crate::warn!("Invalid log level \"{value}\", set to error to disable non-error logging. Defaulting to error"); + log_impl::Level::Error + } + _ => { + crate::warn!("Invalid log level \"{value}\", ignoring"); + continue 'settings; + } + }; + let mut scope_buf = [""; SCOPE_DEPTH_MAX]; + for (index, scope) in key.split(SCOPE_STRING_SEP).enumerate() { + let Some(scope_ptr) = scope_buf.get_mut(index) else { + crate::warn!("Invalid scope key, too many nested scopes: '{key}'"); + continue 'settings; + }; + *scope_ptr = scope; + } + let scope = scope_buf.map(|s| s.to_string()); + map_new.insert(scope, level); + } + + if let Ok(_) = SCOPE_MAP_HASH.compare_exchange( + hash_old, + hash_new, + Ordering::Release, + Ordering::Relaxed, + ) { + let mut map = SCOPE_MAP.write().unwrap_or_else(|err| { + SCOPE_MAP.clear_poison(); + err.into_inner() + }); + *map = Some(map_new.clone()); + // note: hash update done here to ensure consistency with scope map + } + eprintln!("Updated log scope settings :: map = {:?}", map_new); + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_crate_name() { + assert_eq!(crate_name!(), "zlog"); + } +} diff --git a/crates/zlog_settings/Cargo.toml b/crates/zlog_settings/Cargo.toml new file mode 100644 index 0000000000..091fa633c3 --- /dev/null +++ b/crates/zlog_settings/Cargo.toml @@ -0,0 +1,23 @@ +[package] +name = "zlog_settings" +version = "0.1.0" +edition.workspace = true +publish.workspace = true +license = "GPL-3.0-or-later" + +[lints] +workspace = true + +[lib] +path = "src/zlog_settings.rs" + +[features] +default = [] + +[dependencies] +anyhow.workspace = true +gpui.workspace = true +schemars.workspace = true +serde.workspace = true +settings.workspace = true +zlog.workspace = true diff --git a/crates/zlog_settings/LICENSE-GPL b/crates/zlog_settings/LICENSE-GPL new file mode 120000 index 0000000000..89e542f750 --- /dev/null +++ b/crates/zlog_settings/LICENSE-GPL @@ -0,0 +1 @@ +../../LICENSE-GPL \ No newline at end of file diff --git a/crates/zlog_settings/src/zlog_settings.rs b/crates/zlog_settings/src/zlog_settings.rs new file mode 100644 index 0000000000..2553a8874e --- /dev/null +++ b/crates/zlog_settings/src/zlog_settings.rs @@ -0,0 +1,35 @@ +//! # zlog_settings +use anyhow::Result; +use gpui::App; +use schemars::JsonSchema; +use serde::{Deserialize, Serialize}; +use settings::{Settings, SettingsStore}; + +pub fn init(cx: &mut App) { + ZlogSettings::register(cx); + + cx.observe_global::(|cx| { + let zlog_settings = ZlogSettings::get_global(cx); + zlog::scope_map::refresh(&zlog_settings.scopes); + }) + .detach(); +} + +#[derive(Clone, Debug, Default, Serialize, Deserialize, PartialEq, Eq, JsonSchema)] +pub struct ZlogSettings { + #[serde(default, flatten)] + pub scopes: std::collections::HashMap, +} + +impl Settings for ZlogSettings { + const KEY: Option<&'static str> = Some("log"); + + type FileContent = Self; + + fn load(sources: settings::SettingsSources, _: &mut App) -> Result + where + Self: Sized, + { + sources.json_merge() + } +}