feature: add verbose flag and tracing library

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

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"

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" }

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"

src/cli_util.rs

@@ -1202,6 +1202,9 @@ pub struct GlobalArgs {
         help_heading = "Global Options"
     )]
     pub config_toml: Vec<String>,
+    /// Enable verbose logging
+    #[arg(long, short = 'v', global = true, help_heading = "Global Options")]
+    pub verbose: bool,
 }
 
 pub fn create_ui() -> (Ui, Result<(), CommandError>) {

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<EnvFilter, impl tracing::Subscriber>,
+) -> 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);
 }

tests/test_global_opts.rs

@@ -254,5 +254,30 @@ fn test_help() {
           --at-operation <AT_OPERATION>  Operation to load the repo at [default: @] [aliases: at-op]
           --color <WHEN>                 When to colorize output (always, never, auto)
           --config-toml <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");
+}