Make tracing more user-friendly (#46)

CHANGELOG.md

@@ -10,13 +10,22 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## Unreleased
 
+### Added
+
+- Added a new `--verbose` flag to CLI commands in Rokit for easier debugging when something goes wrong ([#46])
+
+### Changed
+
+- Removed warnings with additional information when searching for tool fallbacks, in favor of using the new `--verbose` flag ([#46])
+
 ### Fixed
 
 - Fixed Rokit erroring on first startup due to some directories not yet being created ([#42])
 - Fixed `selene` and other tools not being installable because their releases contain multiple archives / binaries ([#45])
 
 [#42]: https://github.com/rojo-rbx/rokit/pull/42
 [#45]: https://github.com/rojo-rbx/rokit/pull/45
+[#46]: https://github.com/rojo-rbx/rokit/pull/46
 
 ## `0.1.7` - July 15th, 2024
 

lib/descriptor/executable_parsing.rs

@@ -9,7 +9,7 @@ use super::{Arch, OS};
 
     Currently supports ELF, Mach-O and PE formats.
 */
-#[tracing::instrument(skip(binary_contents), level = "debug")]
+#[tracing::instrument(skip(binary_contents), level = "trace")]
 pub fn parse_executable(binary_contents: impl AsRef<[u8]>) -> Option<(OS, Arch)> {
     let binary_contents = binary_contents.as_ref();
 
@@ -38,7 +38,7 @@ pub fn parse_executable(binary_contents: impl AsRef<[u8]>) -> Option<(OS, Arch)>
             .or_else(|| parse_mach(binary_contents))
     };
 
-    tracing::debug!(
+    tracing::trace!(
         elapsed = ?start.elapsed(),
         "parsed executable format"
     );

lib/sources/decompression.rs

@@ -17,7 +17,7 @@ pub async fn decompress_gzip(gz_contents: impl AsRef<[u8]>) -> RokitResult<Vec<u
         let mut contents = Vec::new();
         decoder.read_to_end(&mut contents)?;
 
-        tracing::debug!(
+        tracing::trace!(
             num_kilobytes,
             elapsed = ?start.elapsed(),
             "decompressed gzip"

src/cli/mod.rs

@@ -1,9 +1,12 @@
 use anyhow::{Context, Result};
-use clap::Parser;
+use clap::{ArgAction, Parser};
 use tokio::time::Instant;
+use tracing::level_filters::LevelFilter;
 
 use rokit::storage::Home;
 
+use crate::util::init_tracing;
+
 mod add;
 mod authenticate;
 mod init;
@@ -31,11 +34,16 @@ use self::update::UpdateSubcommand;
 pub struct Cli {
     #[clap(subcommand)]
     pub subcommand: Subcommand,
+    #[clap(flatten)]
+    pub options: GlobalOptions,
 }
 
 impl Cli {
     pub async fn run(self) -> Result<()> {
-        // 1. Load Rokit data structures
+        // 1. Enable the appropriate level of tracing / logging
+        init_tracing(self.options.tracing_level_filter());
+
+        // 2. Load Rokit data structures
         let start_home = Instant::now();
         let home = Home::load_from_env().await.context(
             "Failed to load Rokit home!\
@@ -46,7 +54,7 @@ impl Cli {
             "Rokit loaded"
         );
 
-        // 2. Run the subcommand and capture the result - note that we
+        // 3. Run the subcommand and capture the result - note that we
         // do not (!!!) use the question mark operator here, because we
         // want to save our data below even if the subcommand fails.
         let start_command = Instant::now();
@@ -57,7 +65,7 @@ impl Cli {
             "Rokit ran",
         );
 
-        // 3. Save Rokit data structures to disk
+        // 4. Save Rokit data structures to disk
         let start_save = Instant::now();
         home.save().await.context(
             "Failed to save Rokit data!\
@@ -68,7 +76,7 @@ impl Cli {
             "Rokit saved"
         );
 
-        // 4. Return the result of the subcommand
+        // 5. Return the result of the subcommand
         result
     }
 }
@@ -103,3 +111,19 @@ impl Subcommand {
         }
     }
 }
+
+#[derive(Debug, Parser)]
+pub struct GlobalOptions {
+    #[clap(short, long, action = ArgAction::Count)]
+    pub verbose: u8,
+}
+
+impl GlobalOptions {
+    pub fn tracing_level_filter(&self) -> LevelFilter {
+        match self.verbose {
+            0 => LevelFilter::INFO,
+            1 => LevelFilter::DEBUG,
+            _ => LevelFilter::TRACE,
+        }
+    }
+}

src/main.rs

@@ -9,22 +9,33 @@ mod util;
 
 use self::cli::Cli;
 use self::runner::Runner;
-use self::util::init_tracing;
 
 #[tokio::main]
 async fn main() {
-    init_tracing();
+    /*
+        Rokit has two modes of operation, depending on if
+        it is currently wrapping a tool executable or not:
 
+        - If it is wrapping a tool executable, it will
+          run that executable and pipe its output back
+        - If it is not wrapping a tool executable, it will
+          run a CLI interface for managing / installing tools
+    */
     let runner = Runner::new();
     let result = if runner.should_run() {
         runner.run().await
     } else {
         Cli::parse().run().await
     };
 
-    // NOTE: We use tracing for errors here for consistent
-    // output between returned errors, and errors that
-    // may be logged while the program is running.
+    /*
+        NOTE: We use tracing for errors here for consistent
+        output formatting between returned errors, and errors
+        that may be logged while a wrapped executable is running.
+
+        For more information about how tracing is set up, check the
+        respective `run` methods for the `Cli` and `Runner` structs.
+    */
     if let Err(e) = result {
         error!("{e:?}");
         exit(1);

src/runner/mod.rs

@@ -1,6 +1,7 @@
 use std::{env::args, process::exit, str::FromStr};
 
 use anyhow::{bail, Error, Result};
+use tracing::level_filters::LevelFilter;
 
 use rokit::{
     discovery::{discover_non_rokit_tool, discover_tool_spec},
@@ -9,7 +10,10 @@ use rokit::{
     tool::ToolAlias,
 };
 
+use crate::util::init_tracing;
+
 mod info;
+
 use self::info::inform_user_about_potential_fixes;
 
 #[derive(Debug, Clone)]
@@ -29,6 +33,11 @@ impl Runner {
     }
 
     pub async fn run(&self) -> Result<()> {
+        // Always log at INFO level when running a managed program
+        // unless the user has explicitly set a different level
+        // using the RUST_LOG environment variable.
+        init_tracing(LevelFilter::INFO);
+
         let alias = ToolAlias::from_str(&self.exe_name)?;
 
         let home = Home::load_from_env().await?;

src/util/artifacts.rs

@@ -1,8 +1,8 @@
 use anyhow::{Context, Result};
 
 use rokit::{
-    descriptor::Descriptor,
-    sources::{Artifact, ArtifactProvider},
+    descriptor::{Arch, OS},
+    sources::Artifact,
     tool::ToolId,
 };
 
@@ -12,58 +12,27 @@ pub fn find_most_compatible_artifact(artifacts: &[Artifact], tool_id: &ToolId) -
         .cloned();
 
     if artifact_opt.is_none() {
-        let current_desc = Descriptor::current_system();
-
-        // If we failed to find an artifact compatible with the current system,
-        // we may be able to give additional information to Rokit's users, or tool
-        // maintainers who want to be Rokit-compatible, by examining the artifacts
-        let no_artifacts_with_arch = artifacts.iter().all(|artifact| {
-            artifact
-                .name
-                .as_deref()
-                .and_then(Descriptor::detect)
-                .map_or(false, |desc| desc.arch().is_none())
-        });
-        let additional_information = if no_artifacts_with_arch {
-            let source_is_github = artifacts
-                .iter()
-                .all(|artifact| matches!(artifact.provider, ArtifactProvider::GitHub));
-            let source_name = if source_is_github {
-                "GitHub release files"
-            } else {
-                "tool release files"
-            };
-            Some(format!(
-                "This seems to have been caused by {0} not \
-                specifying an architecture in any of its artifacts.\
-                \nIf you are the maintainer of this tool, you can resolve \
-                this issue by specifying an architecture in {source_name}:\
-                \n    {0}-{1}-{2}.zip",
-                tool_id.name(),
-                current_desc.os().as_str(),
-                current_desc.arch().expect("no current arch (??)").as_str(),
-            ))
-        } else {
-            None
-        };
-
-        // Let the user know about failing to find an artifact,
-        // potentially with additional information generated above
-        tracing::warn!(
-            "Failed to find a fully compatible artifact for {tool_id}!{}\
-            \nSearching for a fallback...",
-            match additional_information {
-                Some(info) => format!("\n{info}"),
-                None => String::new(),
-            }
-        );
-
         if let Some(artifact) = Artifact::find_partially_compatible_fallback(artifacts) {
-            tracing::info!(
-                "Found fallback artifact '{}' for tool {tool_id}",
-                artifact.name.as_deref().unwrap_or("N/A")
+            tracing::debug!(
+                %tool_id,
+                name = %artifact.name.as_deref().unwrap_or("N/A"),
+                "found fallback artifact for tool",
             );
             artifact_opt.replace(artifact);
+        } else {
+            // If we failed to find an artifact compatible with the current system,
+            // we may be able to give additional information to Rokit's users, or tool
+            // maintainers who want to be Rokit-compatible, by examining the artifacts
+            let artifact_names = artifacts
+                .iter()
+                .filter_map(|artifact| artifact.name.as_deref())
+                .collect::<Vec<_>>();
+            tracing::debug!(
+                %tool_id,
+                missing_os_all = %artifact_names.iter().all(|s| OS::detect(s).is_none()),
+                missing_arch_all = %artifact_names.iter().all(|s| Arch::detect(s).is_none()),
+                "missing compatible artifact or fallback for tool"
+            );
         }
     }
 

src/util/tracing.rs

@@ -9,13 +9,12 @@ const FMT_PRETTY: bool = true;
 #[cfg(not(debug_assertions))]
 const FMT_PRETTY: bool = false;
 
-pub fn init() {
+pub fn init(default_level_filter: LevelFilter) {
     let tracing_env_filter = EnvFilter::builder()
-        .with_default_directive(LevelFilter::INFO.into())
+        .with_default_directive(default_level_filter.into())
         .from_env_lossy()
         // Adding the below extra directives will let us debug
         // Rokit easier using RUST_LOG=debug or RUST_LOG=trace
-        .add_directive("octocrab=info".parse().unwrap())
         .add_directive("reqwest=info".parse().unwrap())
         .add_directive("rustls=info".parse().unwrap())
         .add_directive("tokio_util=info".parse().unwrap())
@@ -24,20 +23,12 @@ pub fn init() {
         .add_directive("hyper=info".parse().unwrap())
         .add_directive("h2=info".parse().unwrap());
 
-    // Use the excessively verbose and pretty tracing-subscriber during
-    // development, and a more concise and less pretty output in production.
-    if FMT_PRETTY {
-        tracing_subscriber::fmt()
-            .with_env_filter(tracing_env_filter)
-            .with_writer(stderr)
-            .pretty()
-            .init();
-    } else {
-        tracing_subscriber::fmt()
-            .with_env_filter(tracing_env_filter)
-            .with_writer(stderr)
-            .with_target(false)
-            .without_time()
-            .init();
-    }
+    // Show the target module in the tracing output during development
+    // so that we can track down issues and trace origins faster.
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_env_filter)
+        .with_writer(stderr)
+        .with_target(FMT_PRETTY)
+        .without_time()
+        .init();
 }