From ca201e4c558991d410b75d8ad308d3db832e09cd Mon Sep 17 00:00:00 2001 From: Filip Tibell Date: Tue, 16 Jul 2024 14:30:58 +0200 Subject: [PATCH] Make tracing more user-friendly (#46) --- CHANGELOG.md | 9 ++++ lib/descriptor/executable_parsing.rs | 4 +- lib/sources/decompression.rs | 2 +- src/cli/mod.rs | 34 +++++++++++-- src/main.rs | 21 ++++++-- src/runner/mod.rs | 9 ++++ src/util/artifacts.rs | 71 ++++++++-------------------- src/util/tracing.rs | 29 ++++-------- 8 files changed, 96 insertions(+), 83 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2a0153e..a749795 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,14 @@ 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]) @@ -17,6 +25,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 [#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 diff --git a/lib/descriptor/executable_parsing.rs b/lib/descriptor/executable_parsing.rs index f73f1fb..0856746 100644 --- a/lib/descriptor/executable_parsing.rs +++ b/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" ); diff --git a/lib/sources/decompression.rs b/lib/sources/decompression.rs index 2cf0080..aca9461 100644 --- a/lib/sources/decompression.rs +++ b/lib/sources/decompression.rs @@ -17,7 +17,7 @@ pub async fn decompress_gzip(gz_contents: impl AsRef<[u8]>) -> RokitResult 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, + } + } +} diff --git a/src/main.rs b/src/main.rs index 542d1f8..a5a0b82 100644 --- a/src/main.rs +++ b/src/main.rs @@ -9,12 +9,18 @@ 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 @@ -22,9 +28,14 @@ async fn main() { 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); diff --git a/src/runner/mod.rs b/src/runner/mod.rs index 2a67a84..804a5d9 100644 --- a/src/runner/mod.rs +++ b/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?; diff --git a/src/util/artifacts.rs b/src/util/artifacts.rs index 00376f2..13a39c9 100644 --- a/src/util/artifacts.rs +++ b/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::>(); + 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" + ); } } diff --git a/src/util/tracing.rs b/src/util/tracing.rs index c9227de..6afb7c3 100644 --- a/src/util/tracing.rs +++ b/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(); }