From f5a0c9c5e974a2c5875677882b9d9ac43c12bac1 Mon Sep 17 00:00:00 2001 From: Josh Rotenberg Date: Sat, 18 Apr 2026 22:15:17 -0700 Subject: [PATCH] feat: add tracing instrumentation for command execution Wraps `DockerCommand::execute`, `StreamableCommand::stream`, and the compose, buildx, and swarm paths (all of which funnel through `CommandExecutor::execute_command`) in a top-level `docker.command` info span carrying `command`, `args_count`, `platform`, `runtime`, and `timeout_secs` fields. Successful exits emit `info!` with `duration_ms` + `exit_code`; non-zero exits emit `warn!` with the same plus a 512-byte truncated stderr snippet. Streaming variants run under a `docker.stream` span and emit `debug!` per stdout/stderr line so noisy paths can be filtered at the subscriber level. Instrumentation is gated behind a new `tracing` cargo feature, enabled by default. Building with `--no-default-features` drops the `tracing` dependency entirely; the existing `use tracing::*;` sites now go through a small internal `tracing_compat` shim that re-exports the real macros when the feature is on and expands to no-ops otherwise. Closes #241 --- Cargo.toml | 9 ++- README.md | 61 ++++++++++++++++ src/command.rs | 107 ++++++++++++++++++++++------ src/command/build.rs | 4 +- src/command/logs.rs | 4 +- src/command/run.rs | 4 +- src/debug.rs | 35 ++++++---- src/lib.rs | 5 ++ src/prerequisites.rs | 3 +- src/stream.rs | 116 +++++++++++++++++++++++++++---- src/template.rs | 2 +- src/tracing_compat.rs | 87 +++++++++++++++++++++++ tests/tracing_instrumentation.rs | 74 ++++++++++++++++++++ 13 files changed, 455 insertions(+), 56 deletions(-) create mode 100644 src/tracing_compat.rs create mode 100644 tests/tracing_instrumentation.rs diff --git a/Cargo.toml b/Cargo.toml index 71d8849a..b53efb6a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,10 +21,13 @@ all-features = true rustdoc-args = ["--cfg", "docsrs"] [features] -default = ["compose", "swarm", "manifest"] +default = ["compose", "swarm", "manifest", "tracing"] compose = [] swarm = [] manifest = [] +# Emit `tracing` spans/events from command execution paths. +# Enabled by default; disable with --no-default-features to compile out. +tracing = ["dep:tracing"] # Template features templates = [ @@ -66,7 +69,7 @@ tokio = { version = "1.46", features = [ serde = { version = "1.0", features = ["derive"] } serde_json = "1.0" thiserror = "2.0" -tracing = "0.1" +tracing = { version = "0.1", optional = true } async-trait = "0.1" # Optional dependencies for templates @@ -77,7 +80,9 @@ which = "8.0" [dev-dependencies] tokio-test = "0.4" +tracing = "0.1" tracing-subscriber = "0.3" +tracing-test = { version = "0.2", features = ["no-env-filter"] } uuid = { version = "1.0", features = ["v4"] } futures = "0.3" tempfile = "3.0" diff --git a/README.md b/README.md index c9ba41dc..dc95d713 100644 --- a/README.md +++ b/README.md @@ -79,6 +79,67 @@ let id = redis.start().await?; redis.stop().await?; ``` +## Tracing + +Every command invocation emits [`tracing`](https://docs.rs/tracing) spans and +events so you can observe Docker CLI activity in production. Instrumentation is +enabled by default via the `tracing` cargo feature; compile with +`--no-default-features` to drop the dependency entirely. + +```toml +# Default: tracing instrumentation is on +docker-wrapper = "0.10" + +# Opt out +docker-wrapper = { version = "0.10", default-features = false, features = ["compose"] } +``` + +### What gets emitted + +Each call to `DockerCommand::execute` and `StreamableCommand::stream` is +wrapped in a span: + +| Span | Entered by | Fields | +|---------------------|------------------------------------|-------------------------------------------------------------------| +| `docker.command` | `CommandExecutor::execute_command` | `command`, `args_count`, `platform`, `runtime`, `timeout_secs` | +| `docker.process` | process spawn | `full_command` | +| `docker.timeout` | timeout-wrapped execution | `timeout_secs` | +| `docker.stream` | streaming execution | `command`, `mode` (`handler` or `channel`) | + +Within the `docker.command` span, events are emitted as: + +- `info` on success: `exit_code`, `duration_ms`, `stdout_len`, `stderr_len`. +- `warn` on non-zero exit / spawn failure: `exit_code`, `duration_ms`, + `stderr_snippet` (truncated to ~512 bytes), plus the error message. +- `trace` for raw stdout / stderr payloads. + +Streaming variants additionally emit `debug!` for every stdout/stderr line +(set `RUST_LOG=docker_wrapper=debug` to see them), so noisy builds can be +filtered down by level. + +### Subscribing + +```rust,no_run +use tracing_subscriber::EnvFilter; + +tracing_subscriber::fmt() + .with_env_filter(EnvFilter::try_from_default_env().unwrap_or_else(|_| "docker_wrapper=info".into())) + .init(); +``` + +Useful `RUST_LOG` filters: + +```bash +# All docker-wrapper activity +RUST_LOG=docker_wrapper=trace cargo run + +# Just the top-level execute spans + completion events +RUST_LOG=docker_wrapper=info cargo run + +# Stream commands with per-line output +RUST_LOG=docker_wrapper::stream=debug cargo run +``` + ## Why docker-wrapper? This crate wraps the Docker CLI rather than calling the Docker API directly (like [bollard](https://crates.io/crates/bollard)). diff --git a/src/command.rs b/src/command.rs index a2369e01..580f43d2 100644 --- a/src/command.rs +++ b/src/command.rs @@ -46,6 +46,7 @@ use crate::error::{Error, Result}; use crate::platform::PlatformInfo; +use crate::tracing_compat::{debug, error, info, trace, warn}; use async_trait::async_trait; use std::collections::HashMap; use std::ffi::OsStr; @@ -53,7 +54,6 @@ use std::path::PathBuf; use std::process::Stdio; use std::time::Duration; use tokio::process::Command as TokioCommand; -use tracing::{debug, error, instrument, trace, warn}; // Re-export all command modules pub mod attach; @@ -471,6 +471,28 @@ pub trait ComposeCommand: DockerCommand { /// Default timeout for command execution (30 seconds) pub const DEFAULT_COMMAND_TIMEOUT: Duration = Duration::from_secs(30); +/// Maximum length (in bytes) of stderr snippets attached to tracing events. +/// Bounded so that log sinks don't drown in large error payloads. +const STDERR_LOG_SNIPPET_BYTES: usize = 512; + +/// Truncate `s` to at most `STDERR_LOG_SNIPPET_BYTES`, respecting UTF-8 char +/// boundaries and appending an ellipsis marker when truncation occurs. +#[cfg_attr(not(feature = "tracing"), allow(dead_code))] +fn truncate_for_log(s: &str) -> String { + if s.len() <= STDERR_LOG_SNIPPET_BYTES { + return s.to_string(); + } + // Walk back to a char boundary <= limit. + let mut end = STDERR_LOG_SNIPPET_BYTES; + while end > 0 && !s.is_char_boundary(end) { + end -= 1; + } + let mut out = String::with_capacity(end + 4); + out.push_str(&s[..end]); + out.push_str("..."); + out +} + /// Common functionality for executing Docker commands #[derive(Debug, Clone)] pub struct CommandExecutor { @@ -540,20 +562,41 @@ impl CommandExecutor { } } + /// Get the runtime label suitable for a tracing field (e.g. "docker", + /// "podman"). Returns `None` when no platform has been detected. + #[cfg_attr(not(feature = "tracing"), allow(dead_code))] + fn tracing_platform(&self) -> Option<&'static str> { + use crate::platform::Runtime; + let runtime = self.platform_info.as_ref().map(|p| &p.runtime)?; + Some(match runtime { + Runtime::Docker | Runtime::DockerDesktop => "docker", + Runtime::Podman => "podman", + Runtime::Colima => "colima", + Runtime::RancherDesktop => "rancher-desktop", + Runtime::OrbStack => "orbstack", + }) + } + /// Execute a Docker command with the given arguments /// /// # Errors /// Returns an error if the Docker command fails to execute, returns a non-zero exit code, /// or times out (if a timeout is configured) - #[instrument( - name = "docker.command", - skip(self, args), - fields( - command = %command_name, - runtime = %self.get_runtime_command(), - timeout_secs = self.timeout.map(|t| t.as_secs()), + #[cfg_attr( + feature = "tracing", + tracing::instrument( + name = "docker.command", + skip(self, args), + fields( + command = %command_name, + args_count = args.len(), + platform = self.tracing_platform(), + runtime = %self.get_runtime_command(), + timeout_secs = self.timeout.map(|t| t.as_secs()), + ) ) )] + #[cfg_attr(not(feature = "tracing"), allow(unused_variables))] pub async fn execute_command( &self, command_name: &str, @@ -570,6 +613,8 @@ impl CommandExecutor { trace!(args = ?all_args, "executing docker command"); + let started_at = std::time::Instant::now(); + // Execute with or without timeout let result = if let Some(timeout_duration) = self.timeout { self.execute_with_timeout(&runtime_command, &all_args, timeout_duration) @@ -578,13 +623,16 @@ impl CommandExecutor { self.execute_internal(&runtime_command, &all_args).await }; + let duration_ms = u64::try_from(started_at.elapsed().as_millis()).unwrap_or(u64::MAX); + match &result { Ok(output) => { - debug!( + info!( exit_code = output.exit_code, + duration_ms = duration_ms, stdout_len = output.stdout.len(), stderr_len = output.stderr.len(), - "command completed successfully" + "command completed" ); trace!(stdout = %output.stdout, "command stdout"); if !output.stderr.is_empty() { @@ -592,7 +640,20 @@ impl CommandExecutor { } } Err(e) => { - error!(error = %e, "command failed"); + let (exit_code, stderr_snippet) = match e { + Error::CommandFailed { + exit_code, stderr, .. + } => (Some(*exit_code), Some(truncate_for_log(stderr))), + _ => (None, None), + }; + warn!( + command = %command_name, + exit_code = exit_code, + duration_ms = duration_ms, + stderr_snippet = stderr_snippet.as_deref(), + error = %e, + "command failed" + ); } } @@ -600,11 +661,14 @@ impl CommandExecutor { } /// Internal method to execute a command without timeout - #[instrument( - name = "docker.process", - skip(self, all_args), - fields( - full_command = %format!("{} {}", runtime_command, all_args.join(" ")), + #[cfg_attr( + feature = "tracing", + tracing::instrument( + name = "docker.process", + skip(self, all_args), + fields( + full_command = %format!("{} {}", runtime_command, all_args.join(" ")), + ) ) )] async fn execute_internal( @@ -675,10 +739,13 @@ impl CommandExecutor { } /// Execute a command with a timeout - #[instrument( - name = "docker.timeout", - skip(self, all_args), - fields(timeout_secs = timeout_duration.as_secs()) + #[cfg_attr( + feature = "tracing", + tracing::instrument( + name = "docker.timeout", + skip(self, all_args), + fields(timeout_secs = timeout_duration.as_secs()) + ) )] async fn execute_with_timeout( &self, diff --git a/src/command/build.rs b/src/command/build.rs index 68c4a60c..890c52ba 100644 --- a/src/command/build.rs +++ b/src/command/build.rs @@ -1361,7 +1361,7 @@ impl StreamableCommand for BuildCommand { cmd.arg(arg); } - crate::stream::stream_command(cmd, handler).await + crate::stream::stream_command(cmd, handler, "build").await } async fn stream_channel(&self) -> Result<(mpsc::Receiver, StreamResult)> { @@ -1371,7 +1371,7 @@ impl StreamableCommand for BuildCommand { cmd.arg(arg); } - crate::stream::stream_command_channel(cmd).await + crate::stream::stream_command_channel(cmd, "build").await } } diff --git a/src/command/logs.rs b/src/command/logs.rs index 48f16829..4dc8dde7 100644 --- a/src/command/logs.rs +++ b/src/command/logs.rs @@ -178,7 +178,7 @@ impl StreamableCommand for LogsCommand { cmd.arg(arg); } - crate::stream::stream_command(cmd, handler).await + crate::stream::stream_command(cmd, handler, "logs").await } async fn stream_channel(&self) -> Result<(mpsc::Receiver, StreamResult)> { @@ -189,7 +189,7 @@ impl StreamableCommand for LogsCommand { cmd.arg(arg); } - crate::stream::stream_command_channel(cmd).await + crate::stream::stream_command_channel(cmd, "logs").await } } diff --git a/src/command/run.rs b/src/command/run.rs index 4dc80003..1ae9eb17 100644 --- a/src/command/run.rs +++ b/src/command/run.rs @@ -1833,7 +1833,7 @@ impl StreamableCommand for RunCommand { cmd.arg(arg); } - crate::stream::stream_command(cmd, handler).await + crate::stream::stream_command(cmd, handler, "run").await } async fn stream_channel(&self) -> Result<(mpsc::Receiver, StreamResult)> { @@ -1851,7 +1851,7 @@ impl StreamableCommand for RunCommand { cmd.arg(arg); } - crate::stream::stream_command_channel(cmd).await + crate::stream::stream_command_channel(cmd, "run").await } } diff --git a/src/debug.rs b/src/debug.rs index 3a8220ec..c63c4e22 100644 --- a/src/debug.rs +++ b/src/debug.rs @@ -2,10 +2,10 @@ use crate::command::{CommandExecutor, CommandOutput}; use crate::error::Result; +use crate::tracing_compat::{debug, info, trace, warn}; use std::sync::{Arc, Mutex}; use std::time::Duration; use tokio::time::sleep; -use tracing::{debug, info, instrument, trace, warn}; /// Configuration for dry-run mode and debugging #[derive(Debug, Clone)] @@ -272,13 +272,16 @@ impl DebugExecutor { /// # Errors /// /// Returns an error if the command fails after all retry attempts - #[instrument( - name = "debug.execute", - skip(self, args), - fields( - command = %command_name, - dry_run = self.debug_config.dry_run, - has_retry = self.retry_policy.is_some(), + #[cfg_attr( + feature = "tracing", + tracing::instrument( + name = "debug.execute", + skip(self, args), + fields( + command = %command_name, + dry_run = self.debug_config.dry_run, + has_retry = self.retry_policy.is_some(), + ) ) )] pub async fn execute_command( @@ -324,12 +327,15 @@ impl DebugExecutor { } /// Execute command with retry logic - #[instrument( - name = "debug.retry", - skip(self, args, policy), - fields( - command = %command_name, - max_attempts = policy.max_attempts, + #[cfg_attr( + feature = "tracing", + tracing::instrument( + name = "debug.retry", + skip(self, args, policy), + fields( + command = %command_name, + max_attempts = policy.max_attempts, + ) ) )] async fn execute_with_retry( @@ -401,6 +407,7 @@ impl DebugExecutor { let delay = policy.calculate_delay(attempt); #[allow(clippy::cast_possible_truncation)] + #[cfg_attr(not(feature = "tracing"), allow(unused_variables))] let delay_ms = delay.as_millis() as u64; warn!( attempt = attempt, diff --git a/src/lib.rs b/src/lib.rs index f1c10051..acb54a3e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -403,6 +403,11 @@ pub mod platform; pub mod prerequisites; pub mod stream; +// Internal compatibility shim so the crate can be built without the +// optional `tracing` dependency. Not part of the public API. +#[doc(hidden)] +pub mod tracing_compat; + #[cfg(any( feature = "templates", feature = "template-redis", diff --git a/src/prerequisites.rs b/src/prerequisites.rs index 118c8d7d..c21ff6fd 100644 --- a/src/prerequisites.rs +++ b/src/prerequisites.rs @@ -4,12 +4,12 @@ //! validate version compatibility, and ensure the Docker daemon is running. use crate::error::{Error, Result}; +use crate::tracing_compat::{debug, info, warn}; use serde::{Deserialize, Serialize}; use std::process::Stdio; use std::time::Duration; use tokio::process::Command; use tokio::time::timeout; -use tracing::{debug, info, warn}; use which::which; /// Default timeout for prerequisite checks (30 seconds) @@ -186,6 +186,7 @@ impl DockerPrerequisites { // Check if daemon is running let (daemon_running, server_version) = self.check_daemon(&binary_path).await; + #[cfg_attr(not(feature = "tracing"), allow(clippy::if_same_then_else))] if daemon_running { info!("Docker daemon is running"); } else { diff --git a/src/stream.rs b/src/stream.rs index 9b6d2cca..1b5d6888 100644 --- a/src/stream.rs +++ b/src/stream.rs @@ -4,6 +4,7 @@ //! commands in real-time, rather than waiting for completion. use crate::error::Result; +use crate::tracing_compat::{debug, info, info_span, trace, warn, Instrument}; use async_trait::async_trait; use std::process::Stdio; use tokio::io::{AsyncBufReadExt, BufReader}; @@ -113,17 +114,36 @@ impl StreamHandler { } } -/// Internal helper to spawn a streaming command +/// Internal helper to spawn a streaming command. +/// +/// `command_name` is a short label (e.g. "run", "logs", "build") used for +/// tracing spans; it's purely diagnostic and not passed to the child process. pub(crate) async fn stream_command( + cmd: TokioCommand, + handler: impl FnMut(OutputLine) + Send + 'static, + command_name: &'static str, +) -> Result { + let span = info_span!("docker.stream", command = command_name, mode = "handler",); + stream_command_inner(cmd, handler, command_name) + .instrument(span) + .await +} + +#[cfg_attr(not(feature = "tracing"), allow(unused_variables))] +async fn stream_command_inner( mut cmd: TokioCommand, mut handler: impl FnMut(OutputLine) + Send + 'static, + command_name: &'static str, ) -> Result { cmd.stdout(Stdio::piped()); cmd.stderr(Stdio::piped()); - let mut child = cmd - .spawn() - .map_err(|e| crate::error::Error::custom(format!("Failed to spawn command: {e}")))?; + let started_at = std::time::Instant::now(); + + let mut child = cmd.spawn().map_err(|e| { + warn!(command = command_name, error = %e, "failed to spawn streaming command"); + crate::error::Error::custom(format!("Failed to spawn command: {e}")) + })?; let stdout = child .stdout @@ -147,6 +167,7 @@ pub(crate) async fn stream_command( line = stdout_lines.next_line() => { match line { Ok(Some(text)) => { + debug!(stream = "stdout", line = %text, "stream line"); stdout_accumulator.push(text.clone()); handler(OutputLine::Stdout(text)); } @@ -161,6 +182,7 @@ pub(crate) async fn stream_command( line = stderr_lines.next_line() => { match line { Ok(Some(text)) => { + debug!(stream = "stderr", line = %text, "stream line"); stderr_accumulator.push(text.clone()); handler(OutputLine::Stderr(text)); } @@ -180,26 +202,69 @@ pub(crate) async fn stream_command( .await .map_err(|e| crate::error::Error::custom(format!("Failed to wait for command: {e}")))?; + let exit_code = status.code().unwrap_or(-1); + let success = status.success(); + let duration_ms = u64::try_from(started_at.elapsed().as_millis()).unwrap_or(u64::MAX); + + #[cfg_attr(not(feature = "tracing"), allow(clippy::if_same_then_else))] + if success { + info!( + command = command_name, + exit_code = exit_code, + duration_ms = duration_ms, + stdout_lines = stdout_accumulator.len(), + stderr_lines = stderr_accumulator.len(), + "stream command completed" + ); + } else { + warn!( + command = command_name, + exit_code = exit_code, + duration_ms = duration_ms, + stdout_lines = stdout_accumulator.len(), + stderr_lines = stderr_accumulator.len(), + "stream command exited non-zero" + ); + } + + trace!(command = command_name, "stream finished"); + Ok(StreamResult { - exit_code: status.code().unwrap_or(-1), - success: status.success(), + exit_code, + success, stdout: Some(stdout_accumulator.join("\n")), stderr: Some(stderr_accumulator.join("\n")), }) } -/// Internal helper to spawn a streaming command with channel output +/// Internal helper to spawn a streaming command with channel output. +/// +/// `command_name` is a short diagnostic label used for tracing spans. pub(crate) async fn stream_command_channel( + cmd: TokioCommand, + command_name: &'static str, +) -> Result<(mpsc::Receiver, StreamResult)> { + let span = info_span!("docker.stream", command = command_name, mode = "channel",); + stream_command_channel_inner(cmd, command_name) + .instrument(span) + .await +} + +#[cfg_attr(not(feature = "tracing"), allow(unused_variables))] +async fn stream_command_channel_inner( mut cmd: TokioCommand, + command_name: &'static str, ) -> Result<(mpsc::Receiver, StreamResult)> { let (tx, rx) = mpsc::channel(100); + let started_at = std::time::Instant::now(); cmd.stdout(Stdio::piped()); cmd.stderr(Stdio::piped()); - let mut child = cmd - .spawn() - .map_err(|e| crate::error::Error::custom(format!("Failed to spawn command: {e}")))?; + let mut child = cmd.spawn().map_err(|e| { + warn!(command = command_name, error = %e, "failed to spawn streaming command"); + crate::error::Error::custom(format!("Failed to spawn command: {e}")) + })?; let stdout = child .stdout @@ -218,6 +283,7 @@ pub(crate) async fn stream_command_channel( let mut reader_lines = reader.lines(); let mut lines = Vec::new(); while let Ok(Some(line)) = reader_lines.next_line().await { + debug!(stream = "stdout", line = %line, "stream line"); lines.push(line.clone()); let _ = tx.send(OutputLine::Stdout(line)).await; } @@ -230,6 +296,7 @@ pub(crate) async fn stream_command_channel( let mut reader_lines = reader.lines(); let mut lines = Vec::new(); while let Ok(Some(line)) = reader_lines.next_line().await { + debug!(stream = "stderr", line = %line, "stream line"); lines.push(line.clone()); let _ = tx_clone.send(OutputLine::Stderr(line)).await; } @@ -246,11 +313,36 @@ pub(crate) async fn stream_command_channel( let status = status .map_err(|e| crate::error::Error::custom(format!("Failed to wait for command: {e}")))?; + let exit_code = status.code().unwrap_or(-1); + let success = status.success(); + let duration_ms = u64::try_from(started_at.elapsed().as_millis()).unwrap_or(u64::MAX); + + #[cfg_attr(not(feature = "tracing"), allow(clippy::if_same_then_else))] + if success { + info!( + command = command_name, + exit_code = exit_code, + duration_ms = duration_ms, + stdout_lines = stdout_lines.len(), + stderr_lines = stderr_lines.len(), + "stream command completed" + ); + } else { + warn!( + command = command_name, + exit_code = exit_code, + duration_ms = duration_ms, + stdout_lines = stdout_lines.len(), + stderr_lines = stderr_lines.len(), + "stream command exited non-zero" + ); + } + Ok(( rx, StreamResult { - exit_code: status.code().unwrap_or(-1), - success: status.success(), + exit_code, + success, stdout: Some(stdout_lines.join("\n")), stderr: Some(stderr_lines.join("\n")), }, diff --git a/src/template.rs b/src/template.rs index a0bf66e0..9648f02d 100644 --- a/src/template.rs +++ b/src/template.rs @@ -10,10 +10,10 @@ #![allow(clippy::redundant_closure_for_method_calls)] #![allow(clippy::inefficient_to_string)] +use crate::tracing_compat::{debug, error, info, trace, warn}; use crate::{DockerCommand, RunCommand}; use async_trait::async_trait; use std::collections::HashMap; -use tracing::{debug, error, info, trace, warn}; // Redis templates #[cfg(any( diff --git a/src/tracing_compat.rs b/src/tracing_compat.rs new file mode 100644 index 00000000..9e5bcbf2 --- /dev/null +++ b/src/tracing_compat.rs @@ -0,0 +1,87 @@ +//! Feature-gated re-exports of [`tracing`] macros. +//! +//! Internal compatibility shim that lets call sites emit spans and events without +//! caring whether the `tracing` feature is enabled. When the feature is off, +//! every macro expands to an empty block, and the `tracing` crate is not a +//! compile dependency. +//! +//! Use via `use crate::tracing_compat::{info, debug, ...};` and gate +//! `#[instrument(...)]` attributes with +//! `#[cfg_attr(feature = "tracing", tracing::instrument(...))]` so they also +//! disappear when the feature is off. + +#![allow(unused_imports)] + +#[cfg(feature = "tracing")] +pub(crate) use tracing::{debug, debug_span, error, info, info_span, trace, warn, Instrument}; + +#[cfg(not(feature = "tracing"))] +pub(crate) use self::noop::*; + +#[cfg(not(feature = "tracing"))] +mod noop { + /// No-op replacement for `tracing` event macros (`info!`, `debug!`, ...). + /// + /// Swallows all tokens (fields, format args, target overrides, ...) and + /// expands to an empty block. + #[macro_export] + #[doc(hidden)] + macro_rules! __docker_wrapper_tracing_event_noop { + ($($tt:tt)*) => {{}}; + } + + /// No-op replacement for span-constructor macros (`info_span!`, ...). + /// + /// Swallows all tokens and yields a [`NoopSpan`] value so call sites can use + /// `.entered()` / `.in_scope(...)` / `.record(...)` ergonomics. + #[macro_export] + #[doc(hidden)] + macro_rules! __docker_wrapper_tracing_span_noop { + ($($tt:tt)*) => {{ + $crate::tracing_compat::NoopSpan + }}; + } + + pub(crate) use crate::__docker_wrapper_tracing_event_noop as debug; + pub(crate) use crate::__docker_wrapper_tracing_event_noop as error; + pub(crate) use crate::__docker_wrapper_tracing_event_noop as info; + pub(crate) use crate::__docker_wrapper_tracing_event_noop as trace; + pub(crate) use crate::__docker_wrapper_tracing_event_noop as warn; + pub(crate) use crate::__docker_wrapper_tracing_span_noop as debug_span; + pub(crate) use crate::__docker_wrapper_tracing_span_noop as info_span; +} + +/// Placeholder span returned by [`info_span!`] and friends when the `tracing` +/// feature is disabled. Mirrors the subset of the `tracing::Span` API that the +/// crate uses. +#[cfg(not(feature = "tracing"))] +#[derive(Copy, Clone, Debug)] +pub(crate) struct NoopSpan; + +#[cfg(not(feature = "tracing"))] +#[allow(dead_code, clippy::unused_self, clippy::trivially_copy_pass_by_ref)] +impl NoopSpan { + /// Run `f` within this (no-op) span. Mirrors `tracing::Span::in_scope`. + pub(crate) fn in_scope R, R>(&self, f: F) -> R { + f() + } + + /// Record a field on this (no-op) span. Mirrors `tracing::Span::record`. + pub(crate) fn record(&self, _field: &'static str, _value: V) -> &Self { + self + } +} + +/// Helper trait mirroring `tracing::Instrument` when the feature is disabled. +/// +/// Provides a no-op `.instrument(span)` method on all futures so call sites can +/// use the same ergonomics regardless of feature state. +#[cfg(not(feature = "tracing"))] +pub(crate) trait Instrument: Sized { + fn instrument(self, _span: NoopSpan) -> Self { + self + } +} + +#[cfg(not(feature = "tracing"))] +impl Instrument for T {} diff --git a/tests/tracing_instrumentation.rs b/tests/tracing_instrumentation.rs new file mode 100644 index 00000000..43082b43 --- /dev/null +++ b/tests/tracing_instrumentation.rs @@ -0,0 +1,74 @@ +//! Verify that `DockerCommand::execute` emits the expected tracing spans and +//! events documented in the `Tracing` section of the README. +//! +//! These tests do not require Docker to be installed: they invoke a command +//! that is expected to fail (or to produce a deterministic exit code) via the +//! `GenericCommand` escape hatch and a fake binary path forced onto `PATH`. +//! The assertions are about the tracing output, not about Docker behaviour. + +#![cfg(feature = "tracing")] + +use docker_wrapper::{DockerCommand, GenericCommand}; +use tracing_test::traced_test; + +/// Invoke a command that we expect to fail (a non-existent Docker subcommand +/// using the real docker binary if present, otherwise a spawn failure via a +/// bogus `DOCKER_HOST`). Either branch still produces tracing output. +async fn run_failing_command() { + // `__docker_wrapper_nonexistent__` will never be a valid docker command. + let _ = GenericCommand::new("__docker_wrapper_nonexistent__") + .execute() + .await; +} + +#[tokio::test] +#[traced_test] +async fn docker_command_span_is_emitted() { + run_failing_command().await; + + // The top-level span is named `docker.command` and carries the command + // name as a field. + assert!( + logs_contain("docker.command"), + "expected `docker.command` span to be emitted" + ); + assert!( + logs_contain("__docker_wrapper_nonexistent__"), + "expected command name to appear in tracing fields" + ); +} + +#[tokio::test] +#[traced_test] +async fn failing_command_emits_warn_event() { + run_failing_command().await; + + // Non-zero exit or spawn failure should produce a warn-level "command + // failed" event with a duration_ms field. + assert!( + logs_contain("command failed"), + "expected `command failed` warn event to be emitted" + ); + assert!( + logs_contain("duration_ms"), + "expected `duration_ms` field on the failure event" + ); +} + +#[tokio::test] +#[traced_test] +async fn args_count_is_recorded() { + // Execute a command with a known number of arguments. GenericCommand's + // builder methods consume `self`. + let cmd = GenericCommand::new("__docker_wrapper_nonexistent__") + .arg("--flag-one") + .arg("--flag-two") + .arg("value"); + let _ = cmd.execute().await; + + // The instrument attribute records `args_count` as a span field. + assert!( + logs_contain("args_count"), + "expected `args_count` field to be recorded on the docker.command span" + ); +}