feat: add some more tracing events / structured logs (#494)

crates/cli/Cargo.toml

@@ -76,6 +76,7 @@ tracing = { version = "0.1.40", default-features = false, features = [] }
 notify = "6.1.1"
 notify-debouncer-mini = "0.4.1"
 tracing-subscriber = { version = "0.3", default-features = false, optional = true }
+tracing-log = "0.2.0"
 
 fs-err = { version = "2.11.0" }
 

crates/cli/src/commands/apply.rs

@@ -2,12 +2,12 @@ use anyhow::Result;
 use clap::Args;
 use indicatif::MultiProgress;
 
+use crate::{flags::GlobalFormatFlags, updater::Updater};
 use marzano_messenger::emit::ApplyDetails;
 use serde::Serialize;
 use std::env::current_dir;
 use std::path::PathBuf;
-
-use crate::{flags::GlobalFormatFlags, updater::Updater};
+use tracing::Instrument;
 
 #[cfg(feature = "workflows_v2")]
 use super::apply_migration::{run_apply_migration, ApplyMigrationArgs};
@@ -51,6 +51,9 @@ pub(crate) async fn run_apply(
 ) -> Result<()> {
     #[cfg(feature = "workflows_v2")]
     {
+        let execution_id =
+            std::env::var("GRIT_EXECUTION_ID").unwrap_or_else(|_| uuid::Uuid::new_v4().to_string());
+
         let current_dir = current_dir()?;
         let current_repo_root = marzano_gritmodule::fetcher::LocalRepo::from_dir(&current_dir)
             .await
@@ -73,21 +76,43 @@ pub(crate) async fn run_apply(
             .await;
         }
 
+        let paths = args.paths.clone();
+
         let mut updater = Updater::from_current_bin().await?;
-        let auth = updater.get_valid_auth().await.ok();
+        let auth = updater
+            .get_valid_auth()
+            .instrument(tracing::span!(
+                tracing::Level::INFO,
+                "grit_marzano.auth",
+                "execution_id" = execution_id.as_str(),
+            ))
+            .await
+            .ok();
 
         let custom_workflow =
             crate::workflows::find_workflow_file_from(current_dir, &args.pattern_or_workflow, auth)
+                .instrument(tracing::span!(
+                    tracing::Level::INFO,
+                    "grit_marzano.find_workflow",
+                    "execution_id" = execution_id.as_str(),
+                ))
                 .await;
+
         if let Some(custom_workflow) = custom_workflow {
             return run_apply_migration(
                 custom_workflow,
-                args.paths,
+                paths,
                 ranges,
                 args.apply_migration_args,
                 flags,
                 args.apply_pattern_args.visibility,
+                execution_id.clone(),
             )
+            .instrument(tracing::span!(
+                tracing::Level::INFO,
+                "grit_marzano.run_workflow",
+                "execution_id" = execution_id.as_str(),
+            ))
             .await;
         }
     }

crates/cli/src/commands/apply_migration.rs

@@ -68,6 +68,7 @@ pub(crate) async fn run_apply_migration(
     arg: ApplyMigrationArgs,
     flags: &GlobalFormatFlags,
     min_level: marzano_messenger::emit::VisibilityLevels,
+    execution_id: String,
 ) -> Result<()> {
     use crate::error::GoodError;
 
@@ -90,6 +91,7 @@ pub(crate) async fn run_apply_migration(
     let mut emitter = run_bin_workflow(
         emitter,
         WorkflowInputs {
+            execution_id,
             verbose: arg.verbose,
             workflow_entrypoint: workflow.entrypoint().into(),
             paths,

crates/cli/src/commands/mod.rs

@@ -93,7 +93,6 @@ use std::io::Write;
 use std::process::{ChildStdin, Command, Stdio};
 use std::time::Instant;
 use std::{fmt, process::Child};
-use tracing::instrument;
 use version::VersionArgs;
 
 #[cfg(feature = "workflows_v2")]
@@ -298,34 +297,16 @@ fn write_analytics_event(
     }
 }
 
-#[instrument]
-async fn run_command() -> Result<()> {
-    let app = App::parse();
-    // Use this *only* for analytics, not for any other purpose.
-    let analytics_args = std::env::args().collect::<Vec<_>>();
-
-    // Create and save installation ID if needed
-    let mut updater = Updater::from_current_bin().await?;
-    updater.dump().await?;
-
-    let mut analytics_child =
-        match maybe_spawn_analytics_worker(&app.command, &analytics_args, &updater) {
-            Err(_e) => {
-                log::info!("Failed to start the analytics worker process");
-                // We failed to start the analytics worker process
-                None
-            }
-            Ok(None) => None,
-            Ok(Some(child)) => Some(child),
-        };
+fn setup_env_logger(app: &App, multi: &MultiProgress) {
+    let format: OutputFormat = (&app.format_flags).into();
+    let mut logger = env_logger::Builder::new();
 
     let log_level = app.format_flags.log_level.unwrap_or(match &app.command {
         Commands::Lsp(_) => LevelFilter::Off,
         Commands::Plumbing(_) => LevelFilter::Off,
         _ => LevelFilter::Info,
     });
-    let format: OutputFormat = (&app.format_flags).into();
-    let mut logger = env_logger::Builder::new();
+
     logger.filter_level(log_level);
     logger.target(match format {
         OutputFormat::Standard => env_logger::Target::Stdout,
@@ -342,8 +323,42 @@ async fn run_command() -> Result<()> {
         logger.format(|buf, record| writeln!(buf, "{}", record.args()));
     };
     let logger = logger.build();
+    if let Err(e) = LogWrapper::new(multi.clone(), logger).try_init() {
+        eprintln!("Failed to initialize logger: {:?}", e);
+    }
+}
+
+async fn run_command(use_tracing: bool) -> Result<()> {
+    let app = App::parse();
+    // Use this *only* for analytics, not for any other purpose.
+    let analytics_args = std::env::args().collect::<Vec<_>>();
+
+    // Create and save installation ID if needed
+    let mut updater = Updater::from_current_bin().await?;
+    updater.dump().await?;
+
+    let mut analytics_child =
+        match maybe_spawn_analytics_worker(&app.command, &analytics_args, &updater) {
+            Err(_e) => {
+                log::info!("Failed to start the analytics worker process");
+                // We failed to start the analytics worker process
+                None
+            }
+            Ok(None) => None,
+            Ok(Some(child)) => Some(child),
+        };
+
     let multi = MultiProgress::new();
-    LogWrapper::new(multi.clone(), logger).try_init().unwrap();
+
+    #[cfg(not(feature = "grit_tracing"))]
+    setup_env_logger(&app, &multi);
+    #[cfg(feature = "grit_tracing")]
+    if !use_tracing {
+        setup_env_logger(&app, &multi);
+    } else if let Err(e) = tracing_log::LogTracer::init() {
+        eprintln!("Failed to initialize LogTracer: {:?}", e);
+        setup_env_logger(&app, &multi)
+    }
 
     let command = app.command.to_string();
     let mut apply_details = ApplyDetails {
@@ -364,71 +379,89 @@ async fn run_command() -> Result<()> {
         _ => {
             updater.check_for_update().await?;
         }
-    }
-
-    let res = match app.command {
-        Commands::Apply(arg) => run_apply(arg, multi, &mut apply_details, &app.format_flags).await,
-        Commands::Check(arg) => run_check(arg, &app.format_flags, multi, false, None).await,
-        Commands::List(arg) => run_list_all(&arg, &app.format_flags).await,
-        Commands::Doctor(arg) => run_doctor(arg).await,
-        Commands::Auth(arg) => match arg.auth_commands {
-            AuthCommands::Login(arg) => run_login(arg).await,
-            AuthCommands::Logout(arg) => run_logout(arg).await,
-            AuthCommands::GetToken(arg) => run_get_token(arg).await,
-            AuthCommands::Refresh(arg) => run_refresh_auth(arg).await,
-        },
-        Commands::Lsp(arg) => run_lsp(arg).await,
-        Commands::Install(arg) => run_install(arg).await,
-        Commands::Init(arg) => run_init(arg).await,
-        Commands::Parse(arg) => run_parse(arg, app.format_flags, None).await,
-        Commands::Patterns(arg) => match arg.patterns_commands {
-            PatternCommands::List(arg) => run_patterns_list(arg, app.format_flags).await,
-            PatternCommands::Test(arg) => run_patterns_test(arg, app.format_flags).await,
-            PatternCommands::Edit(arg) => run_patterns_edit(arg).await,
-            PatternCommands::Describe(arg) => run_patterns_describe(arg).await,
-        },
-        #[cfg(feature = "workflows_v2")]
-        Commands::Workflows(arg) => match arg.workflows_commands {
-            WorkflowCommands::List(arg) => run_list_workflows(&arg, &app.format_flags).await,
-            WorkflowCommands::Watch(arg) => run_watch_workflow(&arg, &app.format_flags).await,
-        },
-        Commands::Plumbing(arg) => {
-            run_plumbing(arg, multi, &mut apply_details, app.format_flags).await
-        }
-        Commands::Version(arg) => run_version(arg).await,
-        #[cfg(feature = "docgen")]
-        Commands::Docgen(arg) => run_docgen(arg).await,
-        #[cfg(feature = "server")]
-        Commands::Server(arg) => cli_server::commands::run_server_command(arg).await,
-    };
-    let elapsed = start.elapsed();
-    let details = if command == "apply" {
-        Some(apply_details)
-    } else {
-        None
     };
 
-    let final_analytics_event = match res {
-        Ok(_) => AnalyticsEvent::Completed(CompletedEvent::from_res(elapsed, details)),
+    #[cfg(feature = "grit_tracing")]
+    let cmd_span = span!(
+        Level::INFO,
+        "grit_marzano.run_command",
+        "grit.command" = command.as_str()
+    );
 
-        Err(_) => AnalyticsEvent::Errored(ErroredEvent::from_elapsed(elapsed)),
-    };
+    let runner = async move {
+        let res = match app.command {
+            Commands::Apply(arg) => {
+                run_apply(arg, multi, &mut apply_details, &app.format_flags).await
+            }
+            Commands::Check(arg) => run_check(arg, &app.format_flags, multi, false, None).await,
+            Commands::List(arg) => run_list_all(&arg, &app.format_flags).await,
+            Commands::Doctor(arg) => run_doctor(arg).await,
+            Commands::Auth(arg) => match arg.auth_commands {
+                AuthCommands::Login(arg) => run_login(arg).await,
+                AuthCommands::Logout(arg) => run_logout(arg).await,
+                AuthCommands::GetToken(arg) => run_get_token(arg).await,
+                AuthCommands::Refresh(arg) => run_refresh_auth(arg).await,
+            },
+            Commands::Lsp(arg) => run_lsp(arg).await,
+            Commands::Install(arg) => run_install(arg).await,
+            Commands::Init(arg) => run_init(arg).await,
+            Commands::Parse(arg) => run_parse(arg, app.format_flags, None).await,
+            Commands::Patterns(arg) => match arg.patterns_commands {
+                PatternCommands::List(arg) => run_patterns_list(arg, app.format_flags).await,
+                PatternCommands::Test(arg) => run_patterns_test(arg, app.format_flags).await,
+                PatternCommands::Edit(arg) => run_patterns_edit(arg).await,
+                PatternCommands::Describe(arg) => run_patterns_describe(arg).await,
+            },
+            #[cfg(feature = "workflows_v2")]
+            Commands::Workflows(arg) => match arg.workflows_commands {
+                WorkflowCommands::List(arg) => run_list_workflows(&arg, &app.format_flags).await,
+                WorkflowCommands::Watch(arg) => run_watch_workflow(&arg, &app.format_flags).await,
+            },
+            Commands::Plumbing(arg) => {
+                run_plumbing(arg, multi, &mut apply_details, app.format_flags).await
+            }
+            Commands::Version(arg) => run_version(arg).await,
+            #[cfg(feature = "docgen")]
+            Commands::Docgen(arg) => run_docgen(arg).await,
+            #[cfg(feature = "server")]
+            Commands::Server(arg) => cli_server::commands::run_server_command(arg).await,
+        };
+        let elapsed = start.elapsed();
+        let details = if command == "apply" {
+            Some(apply_details)
+        } else {
+            None
+        };
 
-    write_analytics_event(
-        analytics_child.as_mut().map(|c| c.stdin.as_mut().unwrap()),
-        &final_analytics_event,
-    );
+        let final_analytics_event = match res {
+            Ok(_) => AnalyticsEvent::Completed(CompletedEvent::from_res(elapsed, details)),
 
-    // If we are in the foreground, wait for the analytics worker to finish
-    if is_telemetry_foregrounded() {
-        if let Some(mut child) = analytics_child {
-            log::info!("Waiting for analytics worker to finish");
-            let res = child.wait();
-            if let Err(e) = res {
-                log::info!("Failed to wait for analytics worker: {:?}", e);
+            Err(_) => AnalyticsEvent::Errored(ErroredEvent::from_elapsed(elapsed)),
+        };
+
+        write_analytics_event(
+            analytics_child.as_mut().map(|c| c.stdin.as_mut().unwrap()),
+            &final_analytics_event,
+        );
+
+        // If we are in the foreground, wait for the analytics worker to finish
+        if is_telemetry_foregrounded() {
+            if let Some(mut child) = analytics_child {
+                log::info!("Waiting for analytics worker to finish");
+                let res = child.wait();
+                if let Err(e) = res {
+                    log::info!("Failed to wait for analytics worker: {:?}", e);
+                }
             }
         }
-    }
+
+        res
+    };
+
+    #[cfg(feature = "grit_tracing")]
+    let res = runner.instrument(cmd_span).await;
+    #[cfg(not(feature = "grit_tracing"))]
+    let res = runner.await;
 
     res
 }
@@ -551,7 +584,7 @@ pub async fn run_command_with_tracing() -> Result<()> {
             let res = async move {
                 event!(Level::INFO, "starting the CLI!");
 
-                let res = run_command().await;
+                let res = run_command(true).await;
 
                 event!(Level::INFO, "ending the CLI!");
 
@@ -568,7 +601,7 @@ pub async fn run_command_with_tracing() -> Result<()> {
     let subscriber = tracing::subscriber::NoSubscriber::new();
     tracing::subscriber::set_global_default(subscriber).expect("setting tracing default failed");
 
-    let res = run_command().await;
+    let res = run_command(false).await;
     if let Err(ref e) = res {
         if let Some(good) = e.downcast_ref::<GoodError>() {
             if let Some(msg) = &good.message {