From f0e4615e616ed08f604ce9836b903fe5e6617a3c Mon Sep 17 00:00:00 2001 From: Ruben Slabbert Date: Sun, 20 Nov 2022 13:38:25 +1000 Subject: [PATCH] feature: add verbose flag and tracing library --- CHANGELOG.md | 4 ++ Cargo.lock | 103 ++++++++++++++++++++++++++++++++++++++ Cargo.toml | 2 + lib/Cargo.toml | 1 + src/cli_util.rs | 3 ++ src/main.rs | 36 ++++++++++++- tests/test_global_opts.rs | 25 +++++++++ 7 files changed, 172 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c80ff6d15..23445692a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -67,6 +67,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 * `jj log` will warn if it appears that the provided path was meant to be a revset. +* The new global flag `-v/--verbose` will turn on debug logging to give + some additional insight into what is happening behind the scenes. + Note: This is not comprehensively supported by all operations yet. + ### Fixed bugs * (#463) A bug in the export of branches to Git caused spurious conflicted diff --git a/Cargo.lock b/Cargo.lock index e1559fa27..b9bb25993 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -746,6 +746,8 @@ dependencies = [ "testutils", "textwrap 0.16.0", "thiserror", + "tracing", + "tracing-subscriber", ] [[package]] @@ -779,6 +781,7 @@ dependencies = [ "testutils", "thiserror", "thrift", + "tracing", "uuid", "version_check", "whoami", @@ -868,6 +871,15 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3e2e65a1a2e43cfcb47a895c4c8b10d1f4a61097f9f254f183aee60cad9c651d" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.9" @@ -923,6 +935,16 @@ version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "61807f77802ff30975e01f4f071c8ba10c022052f98b3294119f3e615d13e5be" +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-integer" version = "0.1.45" @@ -1008,6 +1030,12 @@ version = "6.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9ff7415e9ae3fff1225851df9e0d9e4e5479f947619774677a63572e55e80eff" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.1" @@ -1087,6 +1115,12 @@ dependencies = [ "sha1", ] +[[package]] +name = "pin-project-lite" +version = "0.2.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116" + [[package]] name = "pkg-config" version = "0.3.25" @@ -1341,6 +1375,9 @@ name = "regex-automata" version = "0.1.10" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] [[package]] name = "regex-syntax" @@ -1436,6 +1473,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "signal-hook" version = "0.3.14" @@ -1626,6 +1672,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" +dependencies = [ + "once_cell", +] + [[package]] name = "thrift" version = "0.17.0" @@ -1670,6 +1725,54 @@ dependencies = [ "serde", ] +[[package]] +name = "tracing" +version = "0.1.37" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8" +dependencies = [ + "cfg-if", + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4017f8f45139870ca7e672686113917c71c7a6e02d4924eda67186083c03081a" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.30" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a" +dependencies = [ + "once_cell", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "thread_local", + "tracing", + "tracing-core", +] + [[package]] name = "typenum" version = "1.15.0" diff --git a/Cargo.toml b/Cargo.toml index 9eb5c2653..a0adfed53 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -57,6 +57,8 @@ slab = "0.4.7" tempfile = "3.3.0" textwrap = "0.16.0" thiserror = "1.0.37" +tracing = "0.1.37" +tracing-subscriber = { version = "0.3.16", default-features = false, features = ["std", "ansi", "env-filter", "fmt"] } [target.'cfg(unix)'.dependencies] libc = { version = "0.2.137" } diff --git a/lib/Cargo.toml b/lib/Cargo.toml index fbadf1cfb..150cfbaff 100644 --- a/lib/Cargo.toml +++ b/lib/Cargo.toml @@ -43,6 +43,7 @@ thrift = { git = "https://github.com/apache/thrift", rev = "4d493e867b349f347520 uuid = { version = "1.2.2", features = ["v4"] } whoami = "1.2.3" zstd = "0.11.2" +tracing = "0.1.37" [dev-dependencies] assert_matches = "1.5.0" diff --git a/src/cli_util.rs b/src/cli_util.rs index e590fb62b..0fefa4c86 100644 --- a/src/cli_util.rs +++ b/src/cli_util.rs @@ -1202,6 +1202,9 @@ pub struct GlobalArgs { help_heading = "Global Options" )] pub config_toml: Vec, + /// Enable verbose logging + #[arg(long, short = 'v', global = true, help_heading = "Global Options")] + pub verbose: bool, } pub fn create_ui() -> (Ui, Result<(), CommandError>) { diff --git a/src/main.rs b/src/main.rs index 242b7e170..8ec3dfcec 100644 --- a/src/main.rs +++ b/src/main.rs @@ -15,17 +15,49 @@ use jujutsu::cli_util::{create_ui, handle_command_result, parse_args, CommandError}; use jujutsu::commands::{default_app, run_command}; use jujutsu::ui::Ui; +use tracing::metadata::LevelFilter; +use tracing_subscriber::prelude::*; +use tracing_subscriber::reload::Handle; +use tracing_subscriber::EnvFilter; -fn run(ui: &mut Ui) -> Result<(), CommandError> { +fn run( + ui: &mut Ui, + reload_log_filter: Handle, +) -> Result<(), CommandError> { let app = default_app(); let (command_helper, matches) = parse_args(ui, app, std::env::args_os())?; + if command_helper.global_args().verbose { + reload_log_filter + .modify(|filter| { + *filter = EnvFilter::builder() + .with_default_directive(LevelFilter::DEBUG.into()) + .from_env_lossy() + }) + .map_err(|err| { + CommandError::InternalError(format!("failed to enable verbose logging: {:?}", err)) + })?; + tracing::debug!("verbose logging enabled"); + } run_command(ui, &command_helper, &matches) } fn main() { + // TODO(@rslabbert): restructure logging filter setup to better handle + // having verbose logging set up as early as possible, and to support + // custom commands. See discussion on: + // https://github.com/martinvonz/jj/pull/771 + let filter = EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .from_env_lossy(); + let (filter, reload_log_filter) = tracing_subscriber::reload::Layer::new(filter); + tracing_subscriber::registry() + .with(filter) + .with(tracing_subscriber::fmt::Layer::default().with_writer(std::io::stderr)) + .init(); + jujutsu::cleanup_guard::init(); let (mut ui, result) = create_ui(); - let result = result.and_then(|()| run(&mut ui)); + let result = result.and_then(|()| run(&mut ui, reload_log_filter)); let exit_code = handle_command_result(&mut ui, result); std::process::exit(exit_code); } diff --git a/tests/test_global_opts.rs b/tests/test_global_opts.rs index 711e0d114..813fe8bbb 100644 --- a/tests/test_global_opts.rs +++ b/tests/test_global_opts.rs @@ -254,5 +254,30 @@ fn test_help() { --at-operation Operation to load the repo at [default: @] [aliases: at-op] --color When to colorize output (always, never, auto) --config-toml Additional configuration options + -v, --verbose Enable verbose logging "###); } + +#[test] +fn test_verbose_logging_enabled() { + // Test that the verbose flag enabled verbose logging + let test_env = TestEnvironment::default(); + + let assert = test_env + .jj_cmd(test_env.env_root(), &["version", "-v"]) + .assert() + .success(); + + let stderr = get_stderr_string(&assert); + // Split the first log line into a timestamp and the rest. + // The timestamp is constant sized so this is a robust operation. + // Example timestamp: 2022-11-20T06:24:05.477703Z + let (_timestamp, log_line) = stderr + .lines() + .next() + .expect("verbose logging on first line") + .split_at(36); + // The log format is currently Pretty so we include the terminal markup. + // Luckily, insta will print this in colour when reviewing. + insta::assert_snapshot!(log_line, @"\u{1b}[34mDEBUG\u{1b}[0m \u{1b}[2mjj\u{1b}[0m\u{1b}[2m:\u{1b}[0m verbose logging enabled"); +}