diff --git a/Cargo.toml b/Cargo.toml index 6be11dd..2e5bf98 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,6 +19,7 @@ default = ["alternate-registries"] alternate-registries = ["dep:git2"] unstable = [] unstable-toolchain-ci = [] +tracing = ["dep:tracing"] [dependencies] http = "1.1.0" @@ -43,6 +44,7 @@ base64 = "0.22.0" getrandom = { version = "0.4.1", features = ["std"] } thiserror = "2.0.17" git2 = { version = "0.20.2", optional = true } +tracing = { version = "0.1.41", optional = true } [target.'cfg(unix)'.dependencies] nix = { version = "0.30.0", features = ["signal", "user"]} diff --git a/src/build.rs b/src/build.rs index 4d8c95d..05a8a3e 100644 --- a/src/build.rs +++ b/src/build.rs @@ -180,6 +180,18 @@ impl BuildDirectory { } } + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + build_dir = %self.name, + krate = %krate, + toolchain = %toolchain, + patches = patches.len(), + ) + ) + )] pub(crate) fn run anyhow::Result>( &mut self, toolchain: &Toolchain, @@ -203,11 +215,15 @@ impl BuildDirectory { })?; std::fs::create_dir_all(self.target_dir())?; - let res = f(&Build { - dir: self, - toolchain, - sandbox, - })?; + let res = { + #[cfg(feature = "tracing")] + let _entered = tracing::info_span!("build.user_callback").entered(); + f(&Build { + dir: self, + toolchain, + sandbox, + }) + }?; crate::utils::remove_dir_all(&source_dir)?; Ok(res) diff --git a/src/cmd/mod.rs b/src/cmd/mod.rs index f55e99c..f5f2cdb 100644 --- a/src/cmd/mod.rs +++ b/src/cmd/mod.rs @@ -16,6 +16,7 @@ use log::{error, info}; use process_lines_actions::InnerState; use std::env::consts::EXE_SUFFIX; use std::ffi::{OsStr, OsString}; +use std::fmt; use std::mem; use std::path::{Path, PathBuf}; use std::process::{ExitStatus, Stdio}; @@ -142,6 +143,7 @@ impl KillFailedError { /// Name and kind of a binary executed by [`Command`](struct.Command.html). #[non_exhaustive] +#[derive(Debug)] pub enum Binary { /// Global binary, available in `$PATH`. Rustwide doesn't apply any tweaks to its execution /// environment. @@ -213,6 +215,27 @@ pub struct Command<'w, 'pl> { source_dir_mount_kind: MountKind, } +// Custom Debug keeps command output focused: environment variables are shown as keys only, +// since values often contain secrets, and `sandbox`/`process_lines` are summarized as presence +// flags. +impl fmt::Debug for Command<'_, '_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("Command") + .field("is_sandboxed", &self.sandbox.is_some()) + .field("binary", &self.binary) + .field("args", &self.args) + .field("env", &self.env.iter().map(|(k, _)| k).collect::>()) + .field("has_process_lines", &self.process_lines.is_some()) + .field("cd", &self.cd) + .field("timeout", &self.timeout) + .field("no_output_timeout", &self.no_output_timeout) + .field("log_command", &self.log_command) + .field("log_output", &self.log_output) + .field("source_dir_mount_kind", &self.source_dir_mount_kind) + .finish() + } +} + impl<'w> Command<'w, '_> { /// Create a new, unsandboxed command. pub fn new(workspace: &'w Workspace, binary: R) -> Self { @@ -391,6 +414,10 @@ impl<'w> Command<'w, '_> { self.run_inner(true) } + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(self = ?self, capture)) + )] fn run_inner(self, capture: bool) -> Result { if let Some(mut builder) = self.sandbox { let workspace = self diff --git a/src/cmd/sandbox.rs b/src/cmd/sandbox.rs index e0b97d1..a33be38 100644 --- a/src/cmd/sandbox.rs +++ b/src/cmd/sandbox.rs @@ -11,6 +11,7 @@ use std::{ }; /// The Docker image used for sandboxing. +#[derive(Debug)] pub struct SandboxImage { name: String, } @@ -76,7 +77,7 @@ impl SandboxImage { } /// Whether to mount a path in the sandbox with write permissions or not. -#[derive(Copy, Clone, PartialEq, Eq)] +#[derive(Debug, Copy, Clone, PartialEq, Eq)] #[non_exhaustive] pub enum MountKind { /// Allow the sandboxed code to change the mounted data. @@ -240,6 +241,22 @@ impl SandboxBuilder { self } + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + image = %workspace.sandbox_image().name, + mounts = self.mounts.len(), + env = self.env.len(), + memory_limit = ?self.memory_limit, + cpu_limit = ?self.cpu_limit, + cpuset_cpus = ?self.cpuset_cpus, + enable_networking = self.enable_networking, + command = ?self.cmd, + ) + ) + )] fn create(self, workspace: &Workspace) -> Result, CommandError> { let mut args: Vec = vec!["create".into()]; @@ -306,6 +323,25 @@ impl SandboxBuilder { #[allow(clippy::too_many_arguments)] #[allow(clippy::type_complexity)] + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + image = %workspace.sandbox_image().name, + mounts = self.mounts.len(), + env = self.env.len(), + memory_limit = ?self.memory_limit, + cpu_limit = ?self.cpu_limit, + cpuset_cpus = ?self.cpuset_cpus, + enable_networking = self.enable_networking, + command = ?self.cmd, + capture, + timeout_secs = ?timeout.map(|timeout| timeout.as_secs()), + no_output_timeout_secs = ?no_output_timeout.map(|timeout| timeout.as_secs()), + ) + ) + )] pub(super) fn run( self, workspace: &Workspace, @@ -373,6 +409,7 @@ impl fmt::Display for Container<'_> { } impl Container<'_> { + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn inspect(&self) -> Result { let output = Command::new(self.workspace, "docker") .args(&["inspect", &self.id]) @@ -387,6 +424,7 @@ impl Container<'_> { } /// Start the container in detached mode (without `-a`). + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn start(&self) -> Result<(), CommandError> { Command::new(self.workspace, "docker") .args(&["start", &self.id]) @@ -396,6 +434,7 @@ impl Container<'_> { } /// Stop a running container. Uses `-t 1` to give `sleep infinity` a short grace period. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn stop(&self) -> Result<(), CommandError> { Command::new(self.workspace, "docker") .args(&["stop", "-t", "1", &self.id]) @@ -405,6 +444,7 @@ impl Container<'_> { } /// Helper to `docker exec cat ` and return stdout lines on success. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn exec_cat_file(&self, path: &str) -> Option> { Command::new(self.workspace, "docker") .args(&["exec", &self.id, "cat", path]) @@ -417,6 +457,7 @@ impl Container<'_> { /// Best-effort read of peak memory usage from the still-running container. /// Tries cgroups v2 first, then falls back to cgroups v1. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn read_memory_peak(&self) -> Option { let paths = [ "/sys/fs/cgroup/memory.peak", // v2 @@ -439,6 +480,7 @@ impl Container<'_> { /// while `sleep infinity` (PID 1) survives. In that case `docker inspect` won't /// report `OOMKilled`, so we check the cgroup events directly. /// Tries cgroups v2 first, then falls back to cgroups v1. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn check_cgroup_oom(&self) -> bool { // Both v1 and v2 expose `oom_kill ` — just in different files. let paths = [ @@ -463,6 +505,10 @@ impl Container<'_> { } #[allow(clippy::type_complexity)] + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(container_id = %self.id, capture)) + )] fn run( &self, timeout: Option, @@ -536,6 +582,7 @@ impl Container<'_> { } } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn delete(&self) -> Result<(), CommandError> { Command::new(self.workspace, "docker") .args(&["rm", "-f", &self.id]) diff --git a/src/crates/git.rs b/src/crates/git.rs index b24e991..dd17ecc 100644 --- a/src/crates/git.rs +++ b/src/crates/git.rs @@ -63,7 +63,22 @@ impl GitRepo { } impl CrateTrait for GitRepo { + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields(url = %self.url, cache_hit = tracing::field::Empty, path = tracing::field::Empty) + ) + )] fn fetch(&self, workspace: &Workspace) -> anyhow::Result<()> { + let path = self.cached_path(workspace); + let cache_hit = path.join("HEAD").is_file(); + #[cfg(feature = "tracing")] + { + tracing::Span::current().record("cache_hit", cache_hit); + tracing::Span::current().record("path", path.display().to_string()); + } + // The credential helper that suppresses the password prompt shows this message when a // repository requires authentication: // @@ -76,8 +91,7 @@ impl CrateTrait for GitRepo { } }; - let path = self.cached_path(workspace); - let res = if path.join("HEAD").is_file() { + let res = if cache_hit { info!("updating cached repository {}", self.url); Command::new(workspace, "git") .args(&self.suppress_password_prompt_args(workspace)) @@ -113,6 +127,10 @@ impl CrateTrait for GitRepo { Ok(()) } + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(url = %self.url, dest = %dest.display())) + )] fn copy_source_to(&self, workspace: &Workspace, dest: &Path) -> anyhow::Result<()> { Command::new(workspace, "git") .args(&["clone"]) diff --git a/src/crates/local.rs b/src/crates/local.rs index 9679e1d..796da00 100644 --- a/src/crates/local.rs +++ b/src/crates/local.rs @@ -25,6 +25,13 @@ impl CrateTrait for Local { Ok(()) } + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields(source = %self.path.display(), dest = %dest.display()) + ) + )] fn copy_source_to(&self, _workspace: &Workspace, dest: &Path) -> anyhow::Result<()> { info!( "copying local crate from {} to {}", diff --git a/src/crates/mod.rs b/src/crates/mod.rs index d35c9f2..fb3bb10 100644 --- a/src/crates/mod.rs +++ b/src/crates/mod.rs @@ -57,11 +57,19 @@ impl Crate { /// Fetch the crate's source code and cache it in the workspace. This method will reach out to /// the network for some crate types. + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(krate = %self)) + )] pub fn fetch(&self, workspace: &Workspace) -> anyhow::Result<()> { self.as_trait().fetch(workspace) } /// Remove the cached copy of this crate. The method will do nothing if the crate isn't cached. + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(krate = %self)) + )] pub fn purge_from_cache(&self, workspace: &Workspace) -> anyhow::Result<()> { self.as_trait().purge_from_cache(workspace) } @@ -79,6 +87,10 @@ impl Crate { /// copy the source of this crate to the specified destination path. /// /// Will delete the target directory if it already exists. + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(krate = %self, dest = %dest.display())) + )] pub fn copy_source_to(&self, workspace: &Workspace, dest: &Path) -> anyhow::Result<()> { if dest.exists() { info!( diff --git a/src/crates/registry.rs b/src/crates/registry.rs index 8f902a6..68e2c78 100644 --- a/src/crates/registry.rs +++ b/src/crates/registry.rs @@ -96,6 +96,17 @@ impl RegistryCrate { } #[allow(unused_variables)] + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + registry = %self.registry.name(), + crate_name = %self.name, + version = %self.version, + ) + ) + )] fn fetch_url(&self, workspace: &Workspace) -> anyhow::Result { match &self.registry { Registry::CratesIo => Ok(format!( @@ -160,9 +171,25 @@ impl RegistryCrate { } impl CrateTrait for RegistryCrate { + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + registry = %self.registry.name(), + crate_name = %self.name, + version = %self.version, + cache_hit = tracing::field::Empty, + ) + ) + )] fn fetch(&self, workspace: &Workspace) -> anyhow::Result<()> { let local = self.cache_path(workspace); - if local.exists() { + let cache_hit = local.exists(); + #[cfg(feature = "tracing")] + tracing::Span::current().record("cache_hit", cache_hit); + + if cache_hit { info!("crate {} {} is already in cache", self.name, self.version); return Ok(()); } @@ -172,9 +199,11 @@ impl CrateTrait for RegistryCrate { std::fs::create_dir_all(parent)?; } + let url = self.fetch_url(workspace)?; + workspace .http_client() - .get(self.fetch_url(workspace)?) + .get(url) .send()? .error_for_status()? .write_to(&mut BufWriter::new(File::create(&local)?))?; @@ -190,6 +219,18 @@ impl CrateTrait for RegistryCrate { Ok(()) } + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + registry = %self.registry.name(), + crate_name = %self.name, + version = %self.version, + dest = %dest.display(), + ) + ) + )] fn copy_source_to(&self, workspace: &Workspace, dest: &Path) -> anyhow::Result<()> { let cached = self.cache_path(workspace); let mut file = File::open(cached)?; @@ -201,7 +242,9 @@ impl CrateTrait for RegistryCrate { self.version, dest.display() ); - if let Err(err) = unpack_without_first_dir(&mut tar, dest) { + let unpack_result = unpack_without_first_dir(&mut tar, dest); + + if let Err(err) = unpack_result { let _ = crate::utils::remove_dir_all(dest); Err(err.context(format!( "unable to download {} version {}", diff --git a/src/lib.rs b/src/lib.rs index 9d7a653..8bcd567 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -16,6 +16,7 @@ //! * **unstable-toolchain-ci**: allow fetching toolchains from rustc's CI artifacts storage. Support for //! them is **incomplete** (not all methods might work), and there is **no stability guarantee** //! when using them! +//! * **tracing**: emit performance spans for rustwide operations. //! //! [crater]: https://github.com/rust-lang/crater //! [docsrs]: https://github.com/rust-lang/docs.rs diff --git a/src/prepare.rs b/src/prepare.rs index c64e7c6..96710eb 100644 --- a/src/prepare.rs +++ b/src/prepare.rs @@ -33,6 +33,18 @@ impl<'a> Prepare<'a> { } } + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + krate = %self.krate, + toolchain = %self.toolchain, + source_dir = %self.source_dir.display(), + patches = self.patches.len(), + ) + ) + )] pub(crate) fn prepare(&mut self) -> anyhow::Result<()> { self.krate.copy_source_to(self.workspace, self.source_dir)?; self.remove_override_files()?; @@ -44,6 +56,7 @@ impl<'a> Prepare<'a> { Ok(()) } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn validate_manifest(&self) -> anyhow::Result<()> { info!( "validating manifest of {} on toolchain {}", @@ -67,6 +80,7 @@ impl<'a> Prepare<'a> { Ok(()) } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn remove_override_files(&self) -> anyhow::Result<()> { let paths = [ &Path::new(".cargo").join("config"), @@ -84,6 +98,7 @@ impl<'a> Prepare<'a> { Ok(()) } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn tweak_toml(&self) -> anyhow::Result<()> { let path = self.source_dir.join("Cargo.toml"); let mut tweaker = TomlTweaker::new(self.krate, &path, &self.patches)?; @@ -92,6 +107,7 @@ impl<'a> Prepare<'a> { Ok(()) } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn capture_lockfile(&mut self) -> anyhow::Result<()> { if self.source_dir.join("Cargo.lock").exists() { info!( @@ -115,11 +131,23 @@ impl<'a> Prepare<'a> { run_command(cmd.cd(self.source_dir)) } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] fn fetch_deps(&mut self) -> anyhow::Result<()> { fetch_deps(self.workspace, self.toolchain, self.source_dir, &[]) } } +#[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields( + toolchain = %toolchain, + source_dir = %source_dir.display(), + build_std_targets = fetch_build_std_targets.len(), + ) + ) +)] pub(crate) fn fetch_deps( workspace: &Workspace, toolchain: &Toolchain, diff --git a/src/toolchain.rs b/src/toolchain.rs index 119056f..8ce7784 100644 --- a/src/toolchain.rs +++ b/src/toolchain.rs @@ -255,6 +255,10 @@ impl Toolchain { } /// Download and install the toolchain. + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(toolchain = %self)) + )] pub fn install(&self, workspace: &Workspace) -> anyhow::Result<()> { match &self.inner { ToolchainInner::Dist(dist) => dist.init(workspace)?, @@ -303,6 +307,13 @@ impl Toolchain { self.list_rustup_things(workspace, RustupThing::Target) } + #[cfg_attr( + feature = "tracing", + tracing::instrument( + skip_all, + fields(toolchain = %self, action = %action, thing = %thing, name) + ) + )] fn change_rustup_thing( &self, workspace: &Workspace, @@ -375,6 +386,10 @@ impl Toolchain { Ok(()) } + #[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(toolchain = %self, thing = %thing)) + )] fn list_rustup_things( &self, workspace: &Workspace, diff --git a/src/tools/mod.rs b/src/tools/mod.rs index d761caf..97ea833 100644 --- a/src/tools/mod.rs +++ b/src/tools/mod.rs @@ -46,6 +46,10 @@ trait Tool: Send + Sync { } } +#[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(fast_install)) +)] pub(crate) fn install(workspace: &Workspace, fast_install: bool) -> anyhow::Result<()> { for tool in INSTALLABLE_TOOLS { if tool.is_installed(workspace)? { diff --git a/src/utils.rs b/src/utils.rs index d8c3b4d..93d5ea1 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -74,6 +74,10 @@ pub(crate) fn remove_file(path: &Path) -> std::io::Result<()> { std::fs::remove_file(path).map_err(|error| crate::utils::improve_remove_error(error, path)) } +#[cfg_attr( + feature = "tracing", + tracing::instrument(skip_all, fields(path = %path.display())) +)] pub(crate) fn remove_dir_all(path: &Path) -> std::io::Result<()> { remove_dir_all::remove_dir_all(path) .map_err(|error| crate::utils::improve_remove_error(error, path)) diff --git a/src/workspace.rs b/src/workspace.rs index fa8361f..d25b34b 100644 --- a/src/workspace.rs +++ b/src/workspace.rs @@ -21,6 +21,7 @@ const DEFAULT_COMMAND_NO_OUTPUT_TIMEOUT: Option = None; static DEFAULT_RUSTUP_PROFILE: &str = "minimal"; /// Builder of a [`Workspace`](struct.Workspace.html). +#[derive(Debug)] pub struct WorkspaceBuilder { user_agent: String, path: PathBuf, @@ -135,6 +136,7 @@ impl WorkspaceBuilder { /// Initialize the workspace. This will create all the necessary local files and fetch the rest from the network. It's /// not unexpected for this method to take minutes to run on slower network connections. + #[cfg_attr(feature = "tracing", tracing::instrument())] pub fn init(self) -> anyhow::Result { std::fs::create_dir_all(&self.path).with_context(|| { format!( @@ -207,6 +209,7 @@ impl Workspace { } /// Remove all the contents of all the build directories, freeing disk space. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] pub fn purge_all_build_dirs(&self) -> anyhow::Result<()> { let dir = self.builds_dir(); if dir.exists() { @@ -216,6 +219,7 @@ impl Workspace { } /// Remove all the contents of the caches in the workspace, freeing disk space. + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] pub fn purge_all_caches(&self) -> anyhow::Result<()> { let mut paths = vec![ self.cache_dir(), @@ -314,6 +318,7 @@ impl Workspace { &self.inner.rustup_profile } + #[cfg_attr(feature = "tracing", tracing::instrument(skip(self)))] fn init(&self, fast_init: bool) -> anyhow::Result<()> { info!("installing tools required by rustwide"); crate::tools::install(self, fast_init)?; @@ -324,6 +329,7 @@ impl Workspace { Ok(()) } + #[cfg_attr(feature = "tracing", tracing::instrument(skip_all))] #[allow(clippy::unnecessary_wraps)] // hopefully we could actually catch the error here at some point fn update_cratesio_registry(&self) -> anyhow::Result<()> { // This nop cargo command is to update the registry so we don't have to do it for each