diff --git a/.gitignore b/.gitignore index 81d5d39b5..ab79a455b 100644 --- a/.gitignore +++ b/.gitignore @@ -5,3 +5,6 @@ bootc.tar.zst # Added by cargo /target + +# IDEs / Editors +.idea/ diff --git a/Cargo.lock b/Cargo.lock index 9dfc11870..c9585278d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -222,6 +222,7 @@ dependencies = [ "liboverdrop", "libsystemd", "linkme", + "nix", "openssl", "ostree-ext", "regex", diff --git a/docs/src/SUMMARY.md b/docs/src/SUMMARY.md index 3c289037d..df6a2401a 100644 --- a/docs/src/SUMMARY.md +++ b/docs/src/SUMMARY.md @@ -56,6 +56,10 @@ - [bootc image](experimental-bootc-image.md) - [--progress-fd](experimental-progress-fd.md) +- +# Troubleshooting + +- [increasing_logging_verbosity](increasing_logging_verbosity.md) # More information diff --git a/docs/src/increasing_logging_verbosity.md b/docs/src/increasing_logging_verbosity.md new file mode 100644 index 000000000..b717d0158 --- /dev/null +++ b/docs/src/increasing_logging_verbosity.md @@ -0,0 +1,48 @@ +# Increasing Logging Verbosity + +When troubleshooting issues with **bootc**, it is often helpful to enable **verbose logging** to gain additional insights into its execution flow. + +## Using the `--verbose` Flag +Most **bootc** commands support the `--verbose` flag, which enables detailed logging output. The verbosity level determines how much information is logged. + +### **Verbosity Levels** +The `--verbose` flag can be used multiple times (`-v`, `-vv`, `-vvv`) to increase the verbosity of logging: + +| Verbosity Level | Flag Used | Logs Enabled | +|---------------|-----------|--------------| +| **WARN** (default) | *(no flag)* | Only warnings and errors | +| **INFO** | `-v` | Warnings, errors, and general information | +| **DEBUG** | `-vv` | Info, warnings, errors, and debug logs | +| **TRACE** | `-vvv` or more | All logs, including low-level tracing | + +### Example Usage +To switch to a new container image with verbose logging enabled: +```sh +bootc switch --apply -vv quay.io/centos-bootc/centos-bootc:stream9 +``` +This command will print **INFO, DEBUG, and WARN logs**, helping diagnose issues during the `switch` process. + +### Example Output (Verbose Mode Enabled with `-vv`) +```sh +$ bootc switch --apply -vvv quay.io/centos-bootc/centos-bootc:stream9 +TRACE Verified uid 0 with CAP_SYS_ADMIN +DEBUG Re-executing current process for _ostree_unshared +DEBUG Already in a mount namespace +DEBUG Current security context is unconfined_u:system_r:install_t:s0:c1023 +INFO We have install_t +INFO Staged: None +DEBUG Rollback queued=false +DEBUG Wrote merge commit b8761b75924d7f21e7f92abc8fd8b3c645d289fc91555 +DEBUG new_with_config: Spawned skopeo pid=1023 +TRACE new_with_config: impl_request: sending request Initialize +TRACE new_with_config: impl_request: completed request Config=ImageProxy +``` +With `-vvv`, the output includes **INFO, DEBUG, WARN, and TRACE** level messages. + +## Using the `RUST_LOG` Environment Variable +For even more detailed logging, use the `RUST_LOG` environment variable (if applicable for Rust-based components): + +```sh +RUST_LOG=debug bootc switch --apply -vvv quay.io/centos-bootc/centos-bootc:stream9 +``` +The environment variable will override the `-vvv` and enable **DEBUG** level logs for Rust-based sub-components within **bootc**. diff --git a/docs/src/man/bootc-container-lint.md b/docs/src/man/bootc-container-lint.md index 7607d3651..bc49996c2 100644 --- a/docs/src/man/bootc-container-lint.md +++ b/docs/src/man/bootc-container-lint.md @@ -22,6 +22,12 @@ part of a build process; it will error if any problems are detected. : Operate on the provided rootfs +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--fatal-warnings** : Make warnings fatal diff --git a/docs/src/man/bootc-container.md b/docs/src/man/bootc-container.md index 7b8928c4d..0d883b507 100644 --- a/docs/src/man/bootc-container.md +++ b/docs/src/man/bootc-container.md @@ -13,6 +13,12 @@ Operations which can be executed as part of a container build # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help diff --git a/docs/src/man/bootc-edit.md b/docs/src/man/bootc-edit.md index 41b257481..4ece78bd2 100644 --- a/docs/src/man/bootc-edit.md +++ b/docs/src/man/bootc-edit.md @@ -26,6 +26,12 @@ Only changes to the \`spec\` section are honored. : Use filename to edit system specification +**-v**, **\--verbose...** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--quiet** : Dont display progress diff --git a/docs/src/man/bootc-install-ensure-completion.md b/docs/src/man/bootc-install-ensure-completion.md index f532c2541..d785ff1d2 100644 --- a/docs/src/man/bootc-install-ensure-completion.md +++ b/docs/src/man/bootc-install-ensure-completion.md @@ -21,6 +21,12 @@ your code is using \`bootc install to-filesystem\` from the start. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help (see a summary with -h) diff --git a/docs/src/man/bootc-install-print-configuration.md b/docs/src/man/bootc-install-print-configuration.md index bfa266c82..380709089 100644 --- a/docs/src/man/bootc-install-print-configuration.md +++ b/docs/src/man/bootc-install-print-configuration.md @@ -21,6 +21,12 @@ string-valued filesystem name suitable for passing to \`mkfs.\$type\`. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help (see a summary with -h) diff --git a/docs/src/man/bootc-install-to-disk.md b/docs/src/man/bootc-install-to-disk.md index 865968d56..1d4c35454 100644 --- a/docs/src/man/bootc-install-to-disk.md +++ b/docs/src/man/bootc-install-to-disk.md @@ -28,6 +28,12 @@ more complex such as RAID, LVM, LUKS etc. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--wipe** : Automatically wipe all existing data on device diff --git a/docs/src/man/bootc-install-to-existing-root.md b/docs/src/man/bootc-install-to-existing-root.md index bd70d65b5..a6e8020f4 100644 --- a/docs/src/man/bootc-install-to-existing-root.md +++ b/docs/src/man/bootc-install-to-existing-root.md @@ -41,6 +41,12 @@ cleaned up if desired when rebooted into the new root. However, the running system (and all files) will remain in place until reboot +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--source-imgref**=*SOURCE_IMGREF* : Install the system from an explicitly given source. diff --git a/docs/src/man/bootc-install-to-filesystem.md b/docs/src/man/bootc-install-to-filesystem.md index 69732179b..b0807f543 100644 --- a/docs/src/man/bootc-install-to-filesystem.md +++ b/docs/src/man/bootc-install-to-filesystem.md @@ -33,6 +33,12 @@ is currently expected to be empty by default. If not provided, the UUID of the target filesystem will be used. +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--boot-mount-spec**=*BOOT_MOUNT_SPEC* : Mount specification for the /boot filesystem. diff --git a/docs/src/man/bootc-install.md b/docs/src/man/bootc-install.md index bffa66ba4..bdd7a240c 100644 --- a/docs/src/man/bootc-install.md +++ b/docs/src/man/bootc-install.md @@ -30,6 +30,12 @@ includes other setup and metadata. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help (see a summary with -h) diff --git a/docs/src/man/bootc-rollback.md b/docs/src/man/bootc-rollback.md index 35d5a0817..21475bb43 100644 --- a/docs/src/man/bootc-rollback.md +++ b/docs/src/man/bootc-rollback.md @@ -28,6 +28,12 @@ rollback invocation. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help (see a summary with -h) diff --git a/docs/src/man/bootc-status.md b/docs/src/man/bootc-status.md index bf95ce209..b1ad96ba4 100644 --- a/docs/src/man/bootc-status.md +++ b/docs/src/man/bootc-status.md @@ -29,6 +29,12 @@ not \`null\`. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--format**=*FORMAT* : The output format\ diff --git a/docs/src/man/bootc-switch.md b/docs/src/man/bootc-switch.md index 7be8478b2..7ee64512e 100644 --- a/docs/src/man/bootc-switch.md +++ b/docs/src/man/bootc-switch.md @@ -30,6 +30,12 @@ updates via container image tags; for example, : Dont display progress +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--apply** : Restart or reboot into the new target image. diff --git a/docs/src/man/bootc-upgrade.md b/docs/src/man/bootc-upgrade.md index 86d4b8044..17913b0c6 100644 --- a/docs/src/man/bootc-upgrade.md +++ b/docs/src/man/bootc-upgrade.md @@ -31,6 +31,12 @@ the update in addition. : Dont display progress +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **\--check** : Check if an update is available without applying it. diff --git a/docs/src/man/bootc-usr-overlay.md b/docs/src/man/bootc-usr-overlay.md index f8b19e4fd..a4bb56610 100644 --- a/docs/src/man/bootc-usr-overlay.md +++ b/docs/src/man/bootc-usr-overlay.md @@ -33,6 +33,12 @@ unmount\". # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help (see a summary with -h) diff --git a/docs/src/man/bootc.md b/docs/src/man/bootc.md index 87ecf9307..7ed361488 100644 --- a/docs/src/man/bootc.md +++ b/docs/src/man/bootc.md @@ -20,6 +20,12 @@ pulled and \`bootc upgrade\`. # OPTIONS +**-v**, **\--verbose** + +: Increase logging verbosity + + Use `-vv`, `-vvv` to increase verbosity more. + **-h**, **\--help** : Print help (see a summary with -h) diff --git a/lib/Cargo.toml b/lib/Cargo.toml index b4e93dac9..bd461c400 100644 --- a/lib/Cargo.toml +++ b/lib/Cargo.toml @@ -54,6 +54,7 @@ uuid = { version = "1.8.0", features = ["v4"] } tini = "1.3.0" comfy-table = "7.1.1" thiserror = { workspace = true } +nix = "0.27.1" [dev-dependencies] similar-asserts = { workspace = true } diff --git a/lib/src/cli.rs b/lib/src/cli.rs index 958c9cbe4..1e6fa185b 100644 --- a/lib/src/cli.rs +++ b/lib/src/cli.rs @@ -55,6 +55,15 @@ impl TryFrom for ProgressWriter { } } +/// Global args that apply to all subcommands +#[derive(clap::Args, Debug, Clone, Copy, Default)] +#[command(about = None, long_about = None)] +pub(crate) struct GlobalArgs { + /// Increase logging verbosity + #[arg(short = 'v', long = "verbose", action = clap::ArgAction::Count, global = true)] + pub(crate) verbose: u8, // Custom verbosity, counts occurrences of -v +} + /// Perform an upgrade operation #[derive(Debug, Parser, PartialEq, Eq)] pub(crate) struct UpgradeOpts { @@ -460,10 +469,19 @@ impl InternalsOpts { /// whether directly via `bootc install` (executed as part of a container) /// or via another mechanism such as an OS installer tool, further /// updates can be pulled and `bootc upgrade`. -#[derive(Debug, Parser, PartialEq, Eq)] +#[derive(Debug, Parser)] #[clap(name = "bootc")] #[clap(rename_all = "kebab-case")] #[clap(version,long_version=clap::crate_version!())] +pub(crate) struct Cli { + #[clap(flatten)] + pub(crate) global_args: GlobalArgs, + + #[clap(subcommand)] + pub(crate) opt: Opt, // Wrap Opt inside Cli +} + +#[derive(Debug, clap::Subcommand, PartialEq, Eq)] #[allow(clippy::large_enum_variant)] pub(crate) enum Opt { /// Download and queue an updated container image to apply. @@ -988,7 +1006,7 @@ where I: IntoIterator, I::Item: Into + Clone, { - run_from_opt(Opt::parse_including_static(args)).await + run_from_opt(Cli::parse_including_static(args).opt).await } /// Find the base binary name from argv0 (without a full path). The empty string @@ -1003,7 +1021,7 @@ fn callname_from_argv0(argv0: &OsStr) -> &str { .unwrap_or(default) } -impl Opt { +impl Cli { /// In some cases (e.g. systemd generator) we dispatch specifically on argv0. This /// requires some special handling in clap. fn parse_including_static(args: I) -> Self @@ -1027,13 +1045,26 @@ impl Opt { }; if let Some(base_args) = mapped { let base_args = base_args.iter().map(OsString::from); - return Opt::parse_from(base_args.chain(args.map(|i| i.into()))); + return Cli::parse_from(base_args.chain(args.map(|i| i.into()))); } Some(first) } else { None }; - Opt::parse_from(first.into_iter().chain(args.map(|i| i.into()))) + // Parse CLI to extract verbosity level + let cli = Cli::parse_from(first.into_iter().chain(args.map(|i| i.into()))); + + // Set log level based on `-v` occurrences + let log_level = match cli.global_args.verbose { + 0 => tracing::Level::WARN, // Default (no -v) + 1 => tracing::Level::INFO, // -v + 2 => tracing::Level::DEBUG, // -vv + _ => tracing::Level::TRACE, // -vvv or more + }; + + bootc_utils::update_tracing_log_level(log_level); + + cli } } @@ -1198,8 +1229,25 @@ async fn run_from_opt(opt: Opt) -> Result<()> { } } +#[cfg(test)] +mod test_utils { + use std::sync::Once; + use bootc_utils::initialize_tracing; + + // Ensure logging is initialized once to prevent conflicts across tests + static INIT: Once = Once::new(); + + /// Helper function to initialize tracing for tests + pub fn init_tracing_for_tests() { + INIT.call_once(|| { + initialize_tracing(); + }); + } +} + #[cfg(test)] mod tests { + use crate::cli::test_utils::init_tracing_for_tests; use super::*; #[test] @@ -1240,14 +1288,15 @@ mod tests { #[test] fn test_parse_install_args() { // Verify we still process the legacy --target-no-signature-verification - let o = Opt::try_parse_from([ + let o = Cli::try_parse_from([ "bootc", "install", "to-filesystem", "--target-no-signature-verification", "/target", ]) - .unwrap(); + .unwrap() + .opt; let o = match o { Opt::Install(InstallOpts::ToFilesystem(fsopts)) => fsopts, o => panic!("Expected filesystem opts, not {o:?}"), @@ -1263,8 +1312,9 @@ mod tests { #[test] fn test_parse_opts() { + init_tracing_for_tests(); assert!(matches!( - Opt::parse_including_static(["bootc", "status"]), + Cli::parse_including_static(["bootc", "status"]).opt, Opt::Status(StatusOpts { json: false, format: None, @@ -1273,7 +1323,7 @@ mod tests { }) )); assert!(matches!( - Opt::parse_including_static(["bootc", "status", "--format-version=0"]), + Cli::parse_including_static(["bootc", "status", "--format-version=0"]).opt, Opt::Status(StatusOpts { format_version: Some(0), .. @@ -1284,18 +1334,19 @@ mod tests { #[test] fn test_parse_generator() { assert!(matches!( - Opt::parse_including_static([ + Cli::parse_including_static([ "/usr/lib/systemd/system/bootc-systemd-generator", "/run/systemd/system" - ]), + ]).opt, Opt::Internals(InternalsOpts::SystemdGenerator { normal_dir, .. }) if normal_dir == "/run/systemd/system" )); } #[test] fn test_parse_ostree_ext() { + init_tracing_for_tests(); assert!(matches!( - Opt::parse_including_static(["bootc", "internals", "ostree-container"]), + Cli::parse_including_static(["bootc", "internals", "ostree-container"]).opt, Opt::Internals(InternalsOpts::OstreeContainer { .. }) )); @@ -1305,25 +1356,121 @@ mod tests { o => panic!("unexpected {o:?}"), } } - let args = peel(Opt::parse_including_static([ - "/usr/libexec/libostree/ext/ostree-ima-sign", - "ima-sign", - "--repo=foo", - "foo", - "bar", - "baz", - ])); + let args = peel( + Cli::parse_including_static([ + "/usr/libexec/libostree/ext/ostree-ima-sign", + "ima-sign", + "--repo=foo", + "foo", + "bar", + "baz", + ]) + .opt, + ); assert_eq!( args.as_slice(), ["ima-sign", "--repo=foo", "foo", "bar", "baz"] ); - let args = peel(Opt::parse_including_static([ - "/usr/libexec/libostree/ext/ostree-container", - "container", - "image", - "pull", - ])); + let args = peel( + Cli::parse_including_static([ + "/usr/libexec/libostree/ext/ostree-container", + "container", + "image", + "pull", + ]) + .opt, + ); assert_eq!(args.as_slice(), ["container", "image", "pull"]); } } + +#[cfg(test)] +mod tracing_tests { + #![allow(unsafe_code)] + + use bootc_utils::{initialize_tracing, update_tracing_log_level}; + use nix::unistd::{close, dup, dup2, pipe}; + use std::fs::File; + use std::io::{self, Read}; + use std::os::unix::io::{AsRawFd, FromRawFd}; + use std::sync::{Mutex, Once}; + use crate::cli::test_utils::init_tracing_for_tests; + + // Used for ensuring ordered testing of the tracing tests + static TEST_MUTEX: Mutex<()> = Mutex::new(()); + + /// Captures `stderr` output using a pipe + fn capture_stderr(test_fn: F) -> String { + let (read_fd, write_fd) = pipe().expect("Failed to create pipe"); + + // Duplicate original stderr + let original_stderr = dup(io::stderr().as_raw_fd()).expect("Failed to duplicate stderr"); + + // Redirect stderr to the write end of the pipe + dup2(write_fd, io::stderr().as_raw_fd()).expect("Failed to redirect stderr"); + + // Close the write end in the parent to prevent deadlocks + close(write_fd).expect("Failed to close write end"); + + // Run the test function that produces logs + test_fn(); + + // Restore original stderr + dup2(original_stderr, io::stderr().as_raw_fd()).expect("Failed to restore stderr"); + close(original_stderr).expect("Failed to close original stderr"); + + // Read from the pipe + let mut buffer = String::new(); + // File::from_raw_fd() is considered unsafe in Rust, as it takes ownership of a raw file descriptor. + // However, in this case, it's safe because we're using a valid file descriptor obtained from pipe(). + let mut file = unsafe { File::from_raw_fd(read_fd) }; + file.read_to_string(&mut buffer) + .expect("Failed to read from pipe"); + + buffer + } + + #[test] + fn test_default_tracing() { + let _lock = TEST_MUTEX.lock().unwrap(); // Ensure sequential execution + + init_tracing_for_tests(); + + let output = capture_stderr(|| { + tracing::warn!("Test log message to stderr"); + }); + + assert!( + output.contains("Test log message to stderr"), + "Expected log message not found in stderr" + ); + } + + #[test] + fn test_update_tracing() { + let _lock = TEST_MUTEX.lock().unwrap(); // Ensure sequential execution + + init_tracing_for_tests(); + update_tracing_log_level(tracing::Level::TRACE); + + let output = capture_stderr(|| { + tracing::info!("Info message to stderr"); + tracing::debug!("Debug message to stderr"); + tracing::trace!("Trace message to stderr"); + }); + + assert!( + output.contains("Info message to stderr"), + "Expected INFO message not found" + ); + assert!( + output.contains("Debug message to stderr"), + "Expected DEBUG message not found" + ); + assert!( + output.contains("Trace message to stderr"), + "Expected TRACE message not found" + ); + } +} diff --git a/lib/src/docgen.rs b/lib/src/docgen.rs index 53ddc81b4..4bedded64 100644 --- a/lib/src/docgen.rs +++ b/lib/src/docgen.rs @@ -10,7 +10,7 @@ use camino::Utf8Path; use clap::{Command, CommandFactory}; pub fn generate_manpages(directory: &Utf8Path) -> Result<()> { - generate_one(directory, crate::cli::Opt::command()) + generate_one(directory, crate::cli::Cli::command()) } fn generate_one(directory: &Utf8Path, cmd: Command) -> Result<()> { diff --git a/utils/src/tracing_util.rs b/utils/src/tracing_util.rs index 41eea6feb..3e47b5667 100644 --- a/utils/src/tracing_util.rs +++ b/utils/src/tracing_util.rs @@ -1,7 +1,21 @@ //! Helpers related to tracing, used by main entrypoints +use std::sync::{Arc, OnceLock}; +use tracing::Level; +use tracing_subscriber::{ + filter::LevelFilter, fmt, layer::SubscriberExt, reload, EnvFilter, Registry, +}; + +/// Global reload handle for dynamically updating log levels +static TRACING_RELOAD_HANDLE: OnceLock>> = OnceLock::new(); + /// Initialize tracing with the default configuration. pub fn initialize_tracing() { + // Create a reloadable EnvFilter: Use `RUST_LOG` if available, otherwise default to WARN + let env_filter = EnvFilter::try_from_default_env() + .unwrap_or_else(|_| EnvFilter::new(LevelFilter::WARN.to_string())); + let (filter, reload_handle) = reload::Layer::new(env_filter); + // Don't include timestamps and such because they're not really useful and // too verbose, and plus several log targets such as journald will already // include timestamps. @@ -9,11 +23,32 @@ pub fn initialize_tracing() { .without_time() .with_target(false) .compact(); + + // Create a subscriber with a reloadable filter and formatted output // Log to stderr by default - tracing_subscriber::fmt() - .event_format(format) - .with_writer(std::io::stderr) - .with_max_level(tracing::Level::WARN) - .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) - .init(); + let subscriber = Registry::default().with(filter).with( + fmt::layer() + .event_format(format) + .with_writer(std::io::stderr), + ); + + // Set the subscriber globally + tracing::subscriber::set_global_default(subscriber).expect("Failed to set tracing subscriber"); + + // Store the reload handle in a global OnceLock + TRACING_RELOAD_HANDLE.set(Arc::new(reload_handle)).ok(); +} + +/// Update tracing log level dynamically. +pub fn update_tracing_log_level(log_level: Level) { + if let Some(handle) = TRACING_RELOAD_HANDLE.get() { + // Create new filter. Use `RUST_LOG` if available + let new_filter = EnvFilter::try_from_default_env() + .unwrap_or_else(|_| EnvFilter::new(log_level.to_string())); + if let Err(e) = handle.modify(|filter| *filter = new_filter) { + eprintln!("Failed to update log level: {}", e); + } + } else { + panic!("Fatal error: Logging system not initialized. Ensure initialize_tracing() is called first."); + } }