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

Author: joshrotenberg

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"

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)).

src/command.rs

@@ -46,14 +46,14 @@
 
 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;
 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,33 +623,52 @@ 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() {
                     trace!(stderr = %output.stderr, "command stderr");
                 }
             }
             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"
+                );
             }
         }
 
         result
     }
 
     /// 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,

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<OutputLine>, 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
     }
 }
 

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<OutputLine>, 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
     }
 }
 

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<OutputLine>, 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
     }
 }