From 2f7aeba4179814baca1f4c5b23dfb08535675091 Mon Sep 17 00:00:00 2001 From: Bryan Helmkamp Date: Thu, 30 Apr 2026 23:31:20 -0400 Subject: [PATCH] fix(workflow): preserve exec failure diagnostics Add bounded redacted exec output tails to failure events while keeping tracing log-safe. Centralize tail projection on ExecResult and thread diagnostics through metadata, setup, devcontainer, and CLI install failures. --- docs/internal/logging-strategy.md | 16 ++ ...04-30-preserve-exec-failure-diagnostics.md | 78 +++--- .../src/commands/run/run_progress/event.rs | 19 +- .../src/commands/run/run_progress/mod.rs | 38 +-- lib/crates/fabro-sandbox/src/daytona/mod.rs | 15 +- lib/crates/fabro-sandbox/src/error.rs | 118 +++++--- lib/crates/fabro-sandbox/src/sandbox.rs | 260 +++++++++++++++-- lib/crates/fabro-types/src/lib.rs | 2 +- lib/crates/fabro-types/src/run_event/infra.rs | 90 ++++-- lib/crates/fabro-types/src/run_event/mod.rs | 82 +++++- .../fabro-workflow/src/devcontainer_bridge.rs | 31 ++- lib/crates/fabro-workflow/src/event.rs | 237 ++++++++++++---- .../fabro-workflow/src/handler/llm/cli.rs | 68 +++-- .../fabro-workflow/src/lifecycle/git.rs | 22 +- .../fabro-workflow/src/pipeline/finalize.rs | 13 +- .../fabro-workflow/src/pipeline/initialize.rs | 112 +++++++- lib/crates/fabro-workflow/src/sandbox_git.rs | 27 +- .../fabro-workflow/src/sandbox_metadata.rs | 262 +++++++++++++++--- 18 files changed, 1184 insertions(+), 306 deletions(-) diff --git a/docs/internal/logging-strategy.md b/docs/internal/logging-strategy.md index 983800b58..ae886ab5b 100644 --- a/docs/internal/logging-strategy.md +++ b/docs/internal/logging-strategy.md @@ -198,8 +198,24 @@ Some field values carry real or latent sensitivity and must not appear in `traci | `diff_contents` | File contents from a user workspace may include secrets, PII, or copyrighted code. | `bytes_total`, `file_count`, `truncated` counters | | `file_path` (for changed-file paths in the Run Files endpoint specifically) | Leaks workspace structure; combined with public run IDs can expose layout of private repos. | `file_count`, aggregate counts bucketed by `binary`, `sensitive`, `symlink`, `submodule` | | `git_stderr` | Raw git output for untrusted workspaces may include path-shaped secrets (e.g. `~/.ssh/id_rsa_work`) and terminal control sequences. | A short categorized reason (`"timeout"`, `"bad_revision"`, `"unknown_object"`) derived from stderr, never the stderr itself | +| Raw command stdout/stderr, including raw `git_stderr` | Process output for untrusted workspaces may include secrets, PII, paths, or terminal control sequences. Durable run events may include `ExecOutputTail`, which is bounded and redacted before serialization. | In tracing, emit only tail metadata such as presence, byte count, and truncation booleans. | | Credential-ish strings (`api_key`, `bearer_token`, `cookie`, `session_id`, …) | Exfiltration risk. | Emit `has_credentials: true` or a fingerprint (`token_last4`) only when debugging is the only option | These prohibitions apply to every level (ERROR through TRACE). If an error path genuinely needs raw output for triage, route it through an authenticated support channel — not the default tracing subscriber. +Safe tracing for process failures looks like: + +```rust +error!( + command, + exit_code, + exec_output_tail_present, + exec_stdout_tail_bytes, + exec_stdout_truncated, + exec_stderr_tail_bytes, + exec_stderr_truncated, + "Setup command failed" +); +``` + For URLs that may carry credentials, log `fabro_redact::DisplaySafeUrl` or a string produced by `DisplaySafeUrl::redacted_string()`. Its `Display` and `Debug` forms redact userinfo plus these query keys case-insensitively: `token`, `install_token`, `access_token`, `refresh_token`, `api_key`, `apikey`, `code`, `state`, `password`, `secret`, and `key`. Raw URL strings stay reserved for wire transit, subprocess arguments, redirects, and persistence. diff --git a/docs/superpowers/plans/2026-04-30-preserve-exec-failure-diagnostics.md b/docs/superpowers/plans/2026-04-30-preserve-exec-failure-diagnostics.md index 8f868bb8e..260cead67 100644 --- a/docs/superpowers/plans/2026-04-30-preserve-exec-failure-diagnostics.md +++ b/docs/superpowers/plans/2026-04-30-preserve-exec-failure-diagnostics.md @@ -1,6 +1,6 @@ # Preserve Exec Failure Diagnostics Implementation Plan -> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [x]`) syntax for tracking. **Goal:** Preserve bounded, redacted stdout/stderr tails for failed process executions in durable run events, while keeping server tracing log-safe and avoiding duplicate full process-output types. @@ -40,7 +40,7 @@ - Modify: `lib/crates/fabro-types/src/lib.rs` - Modify: `lib/crates/fabro-types/src/run_event/mod.rs` -- [ ] **Step 1: Add `ExecOutputTail`** +- [x] **Step 1: Add `ExecOutputTail`** Add this type near the infrastructure event props in `infra.rs`: @@ -82,7 +82,7 @@ impl ExecOutputTail { Keep `is_false` private to the module. Do not add another full process result type. -- [ ] **Step 2: Add `exec_output_tail` additively to failure props** +- [x] **Step 2: Add `exec_output_tail` additively to failure props** Add this optional field to `MetadataSnapshotFailedProps`, `SetupFailedProps`, `CliEnsureFailedProps`, and `DevcontainerLifecycleFailedProps`: @@ -93,11 +93,11 @@ pub exec_output_tail: Option, Do not remove existing fields, including `stderr` on setup/devcontainer failure props. -- [ ] **Step 3: Re-export the projection** +- [x] **Step 3: Re-export the projection** In `lib.rs`, include `ExecOutputTail` in the `pub use run_event::{ ... }` list if downstream crates need to reference it as `fabro_types::ExecOutputTail`. -- [ ] **Step 4: Add serde tests** +- [x] **Step 4: Add serde tests** Add a test in `run_event/mod.rs` that serializes a `MetadataSnapshotFailedProps` with: @@ -114,7 +114,7 @@ Assert the JSON includes `exec_output_tail.stdout`, `exec_output_tail.stderr`, a Add a second assertion that `exec_output_tail: None` omits the field. -- [ ] **Step 5: Run focused type tests** +- [x] **Step 5: Run focused type tests** Run: @@ -131,7 +131,7 @@ Expected: serde tests pass and existing event payloads remain backward compatibl - Modify: `lib/crates/fabro-sandbox/src/error.rs` - Modify: `lib/crates/fabro-sandbox/src/daytona/mod.rs` -- [ ] **Step 1: Add projection helpers to `ExecResult`** +- [x] **Step 1: Add projection helpers to `ExecResult`** In `sandbox.rs`, add: @@ -178,7 +178,7 @@ pub fn from_process_output(output: std::process::Output, duration_ms: u64) -> Se The signal-killed fallback is `-1`, matching existing local/docker sandbox behavior. The 8 KiB limit is applied after redaction and sanitization, so it is an event-size budget, not a promise about how many original process-output bytes are represented. At the default, one failure event can add at most about 16 KiB of tail text plus JSON escaping overhead. -- [ ] **Step 2: Redact before truncating** +- [x] **Step 2: Redact before truncating** Implement the private helper so it redacts the full stream first, strips ANSI escape sequences and other terminal control characters in the retained diagnostic string, then takes the tail: @@ -245,7 +245,7 @@ fn sanitize_exec_output(text: &str) -> String { If the repository MSRV does not support `str::floor_char_boundary`, use the existing pattern from `fabro-agent/src/truncation.rs` and note that in the implementation comment. -- [ ] **Step 3: Refactor `Error::Exec` to store `ExecResult`** +- [x] **Step 3: Refactor `Error::Exec` to store `ExecResult`** In `error.rs`, replace the existing six-field variant with: @@ -292,7 +292,7 @@ pub fn default_redacted_output_tail(&self) -> Option` to: @@ -364,11 +364,11 @@ Add `exec_output_tail: Option` to: Keep existing `stderr` fields on `SetupFailed` and `DevcontainerLifecycleFailed`. -- [ ] **Step 2: Map tails into `EventBody`** +- [x] **Step 2: Map tails into `EventBody`** In `event_body_from_event`, pass `exec_output_tail.clone()` into the corresponding props for all four variants. -- [ ] **Step 3: Trace only safe tail metadata** +- [x] **Step 3: Trace only safe tail metadata** Do not add `exec_stdout_tail` or `exec_stderr_tail` fields to tracing. In each failure trace arm, include only: @@ -382,7 +382,7 @@ exec_stderr_truncated = exec_output_tail.as_ref().map(|tail| tail.stderr_truncat This preserves the server-log debugging breadcrumb without duplicating output content into `server.log`. -- [ ] **Step 4: Update event tests** +- [x] **Step 4: Update event tests** Update existing constructors in tests to include `exec_output_tail: None`. @@ -390,7 +390,7 @@ Add a test that converts a `SetupFailed` or `MetadataSnapshotFailed` event with Add a test around `build_redacted_event_payload` that uses a secret-looking value in `exec_output_tail` and asserts the persisted payload does not contain the raw token. -- [ ] **Step 5: Run focused event tests** +- [x] **Step 5: Run focused event tests** Run: @@ -407,7 +407,7 @@ Expected: event conversion includes additive tails and tracing changes compile. - Modify: `lib/crates/fabro-workflow/src/lifecycle/git.rs` - Modify: `lib/crates/fabro-workflow/src/pipeline/finalize.rs` -- [ ] **Step 1: Keep `MetadataSnapshot` serializable/simple** +- [x] **Step 1: Keep `MetadataSnapshot` serializable/simple** Do not store `fabro_sandbox::Error` in `MetadataSnapshot`. @@ -433,7 +433,7 @@ to: pub push_error: Option, ``` -- [ ] **Step 2: Capture push tail before stringifying** +- [x] **Step 2: Capture push tail before stringifying** Change the push handling to: @@ -450,7 +450,7 @@ let push_error = match push_result { Return this field on `MetadataSnapshot`. The only valid states are `None` for no push failure, or `Some(MetadataPushError { message, exec_output_tail })` for a push failure. There are no parallel `Option` fields. -- [ ] **Step 3: Carry write-failure tails by projection only** +- [x] **Step 3: Carry write-failure tails by projection only** Change string-only command/sandbox failures in `SandboxMetadataError` to one diagnostic variant carrying the projection, not the full sandbox error: @@ -484,7 +484,7 @@ Use `Operation` for both nonzero `ExecResult` returns and sandbox API errors suc `Dump(#[from] anyhow::Error)` intentionally has no `exec_output_tail`: run-dump serialization should not execute sandbox commands. If a future dump path performs sandbox exec, that code path must return `Operation` instead. -- [ ] **Step 4: Update metadata command helpers** +- [x] **Step 4: Update metadata command helpers** In `exec_stdout`, use: @@ -510,7 +510,7 @@ if result.is_success() { Delete the local `exec_err` helper after callers no longer use it. -- [ ] **Step 5: Emit metadata failed events with tails** +- [x] **Step 5: Emit metadata failed events with tails** In both `lifecycle/git.rs` and `pipeline/finalize.rs`: @@ -518,7 +518,7 @@ In both `lifecycle/git.rs` and `pipeline/finalize.rs`: - For write failures, pass `err.exec_output_tail()`. - Keep the warning message string concise and based on the existing safe error string. -- [ ] **Step 6: Update metadata tests** +- [x] **Step 6: Update metadata tests** Update tests that assert `MetadataSnapshotFailedProps` to include: @@ -550,7 +550,7 @@ Expected: metadata push/write failure events contain `exec_output_tail` when com - Modify: `lib/crates/fabro-workflow/src/devcontainer_bridge.rs` - Modify: `lib/crates/fabro-workflow/src/handler/llm/cli.rs` -- [ ] **Step 1: Add setup failure tails without removing `stderr`** +- [x] **Step 1: Add setup failure tails without removing `stderr`** When a setup command returns a nonzero exit code, emit: @@ -567,7 +567,7 @@ options.emitter.emit(&Event::SetupFailed { Keep the existing `stderr` value for compatibility in this change. -- [ ] **Step 2: Add devcontainer failure tails without removing `stderr`** +- [x] **Step 2: Add devcontainer failure tails without removing `stderr`** For both parallel and single-command lifecycle failures, emit: @@ -585,7 +585,7 @@ emitter.emit(&Event::DevcontainerLifecycleFailed { Use `phase.to_string()` and `command.to_string()` in the single-command path, matching the current code. -- [ ] **Step 3: Replace CLI install's embedded output detail** +- [x] **Step 3: Replace CLI install's embedded output detail** In CLI ensure install failure handling, replace the 500-character manual tail embedded in `error_msg` with: @@ -605,7 +605,7 @@ emitter.emit(&Event::CliEnsureFailed { return Err(Error::handler(error_msg)); ``` -- [ ] **Step 4: Add focused tests** +- [x] **Step 4: Add focused tests** Add or update tests so that: @@ -629,7 +629,7 @@ Expected: failure events are additive and backward compatible. **Files:** - Modify only files that fail to compile from the `Error::exec` signature change. -- [ ] **Step 1: Find old constructor call sites** +- [x] **Step 1: Find old constructor call sites** Run: @@ -639,17 +639,17 @@ rg -n "Error::exec\\(|\\.into_exec_error_with_redactor\\(" lib/crates/fabro-sand Expected: old direct `Error::exec(label, exit_code, timed_out, duration_ms, stderr, stdout)` calls are limited and mechanical. -- [ ] **Step 2: Update direct `Error::exec` calls mechanically** +- [x] **Step 2: Update direct `Error::exec` calls mechanically** For each old direct call, construct an `ExecResult` with the same existing values and pass it to `Error::exec(label, result)`. Do not refactor `sandbox_git.rs` return types unless a compile error forces it. -- [ ] **Step 3: Keep hook behavior unchanged** +- [x] **Step 3: Keep hook behavior unchanged** Do not add hook stdout/stderr tails to `HookDecision::Block.reason`. If compilation requires use of `ExecResult::from_process_output`, use it internally only and preserve the existing decision behavior. -- [ ] **Step 4: Run compile-focused checks** +- [x] **Step 4: Run compile-focused checks** Run: @@ -666,7 +666,7 @@ Expected: constructor refactor compiles without broad unrelated changes. **Files:** - Modify: `docs/internal/logging-strategy.md` -- [ ] **Step 1: Preserve the raw-output prohibition** +- [x] **Step 1: Preserve the raw-output prohibition** Update the prohibited-fields guidance to say: @@ -674,7 +674,7 @@ Update the prohibited-fields guidance to say: Raw command stdout/stderr, including raw `git_stderr`, must not be emitted to tracing logs. Durable run events may include `ExecOutputTail`, which is bounded and redacted before serialization. Tracing may include only tail metadata such as presence, byte count, and truncation booleans. ``` -- [ ] **Step 2: Add a safe tracing example** +- [x] **Step 2: Add a safe tracing example** Add an example like: @@ -693,7 +693,7 @@ error!( Do not show tail content fields in the tracing example. -- [ ] **Step 3: Verify docs mention both sides of the policy** +- [x] **Step 3: Verify docs mention both sides of the policy** Run: @@ -708,7 +708,7 @@ Expected: docs allow bounded redacted tails in events and prohibit raw/tail cont **Files:** - Existing Rust test modules only. -- [ ] **Step 1: Run focused crate tests** +- [x] **Step 1: Run focused crate tests** Run: @@ -720,7 +720,7 @@ cargo nextest run -p fabro-workflow Expected: all focused tests pass. -- [ ] **Step 2: Run hook tests to prove behavior stayed stable** +- [x] **Step 2: Run hook tests to prove behavior stayed stable** Run: @@ -730,7 +730,7 @@ cargo nextest run -p fabro-hooks Expected: existing hook command behavior remains unchanged. -- [ ] **Step 3: Run formatting** +- [x] **Step 3: Run formatting** Run: @@ -740,7 +740,7 @@ cargo +nightly-2026-04-14 fmt --check --all Expected: formatting passes. -- [ ] **Step 4: Run clippy after tests pass** +- [x] **Step 4: Run clippy after tests pass** Run: @@ -750,7 +750,7 @@ cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings Expected: no new warnings. -- [ ] **Step 5: Inspect one event payload** +- [x] **Step 5: Inspect one event payload** Run or unit-test a setup failure and inspect the canonical event. The expected shape is additive: diff --git a/lib/crates/fabro-cli/src/commands/run/run_progress/event.rs b/lib/crates/fabro-cli/src/commands/run/run_progress/event.rs index 366f22555..19c8c2304 100644 --- a/lib/crates/fabro-cli/src/commands/run/run_progress/event.rs +++ b/lib/crates/fabro-cli/src/commands/run/run_progress/event.rs @@ -715,15 +715,16 @@ mod tests { #[test] fn round_trip_metadata_snapshot_failed() { let event = Event::MetadataSnapshotFailed { - phase: MetadataSnapshotPhase::Finalize, - branch: "fabro/meta".into(), - duration_ms: 900, - failure_kind: MetadataSnapshotFailureKind::Push, - error: "push rejected".into(), - causes: vec!["remote rejected".into()], - commit_sha: Some("abc123".into()), - entry_count: Some(2), - bytes: Some(42), + phase: MetadataSnapshotPhase::Finalize, + branch: "fabro/meta".into(), + duration_ms: 900, + failure_kind: MetadataSnapshotFailureKind::Push, + error: "push rejected".into(), + causes: vec!["remote rejected".into()], + commit_sha: Some("abc123".into()), + entry_count: Some(2), + bytes: Some(42), + exec_output_tail: None, }; let stored = to_run_event(&fixtures::RUN_1, &event); diff --git a/lib/crates/fabro-cli/src/commands/run/run_progress/mod.rs b/lib/crates/fabro-cli/src/commands/run/run_progress/mod.rs index b53e0c869..2daef218f 100644 --- a/lib/crates/fabro-cli/src/commands/run/run_progress/mod.rs +++ b/lib/crates/fabro-cli/src/commands/run/run_progress/mod.rs @@ -1042,15 +1042,16 @@ mod tests { commit_sha: "abc123".into(), }); emit(&mut ui, Event::MetadataSnapshotFailed { - phase: MetadataSnapshotPhase::Finalize, - branch: "fabro/meta".into(), - duration_ms: 900, - failure_kind: MetadataSnapshotFailureKind::Push, - error: "push rejected".into(), - causes: Vec::new(), - commit_sha: Some("abc123".into()), - entry_count: Some(2), - bytes: Some(42), + phase: MetadataSnapshotPhase::Finalize, + branch: "fabro/meta".into(), + duration_ms: 900, + failure_kind: MetadataSnapshotFailureKind::Push, + error: "push rejected".into(), + causes: Vec::new(), + commit_sha: Some("abc123".into()), + entry_count: Some(2), + bytes: Some(42), + exec_output_tail: None, }); insta::assert_snapshot!(rendered(&buffer), @"Warning: Metadata finalize failed: push rejected [push]"); @@ -1061,15 +1062,16 @@ mod tests { let (mut ui, buffer) = capture_ui(false); emit(&mut ui, Event::MetadataSnapshotFailed { - phase: MetadataSnapshotPhase::Checkpoint, - branch: "fabro/meta".into(), - duration_ms: 900, - failure_kind: MetadataSnapshotFailureKind::Write, - error: "write failed".into(), - causes: Vec::new(), - commit_sha: None, - entry_count: None, - bytes: None, + phase: MetadataSnapshotPhase::Checkpoint, + branch: "fabro/meta".into(), + duration_ms: 900, + failure_kind: MetadataSnapshotFailureKind::Write, + error: "write failed".into(), + causes: Vec::new(), + commit_sha: None, + entry_count: None, + bytes: None, + exec_output_tail: None, }); emit(&mut ui, Event::RunNotice { level: RunNoticeLevel::Warn, diff --git a/lib/crates/fabro-sandbox/src/daytona/mod.rs b/lib/crates/fabro-sandbox/src/daytona/mod.rs index e51ef58eb..2bdd480f1 100644 --- a/lib/crates/fabro-sandbox/src/daytona/mod.rs +++ b/lib/crates/fabro-sandbox/src/daytona/mod.rs @@ -662,11 +662,16 @@ impl Sandbox for DaytonaSandbox { Ok(r) if r.exit_code != 0 => { let err = crate::Error::exec( "git remote set-url origin (Daytona post-clone)", - Some(r.exit_code), - CommandTermination::Exited, - 0, - redact_auth_url(&r.result, Some(&auth_url)), - String::new(), + ExecResult { + stdout: String::new(), + stderr: redact_auth_url( + &r.result, + Some(&auth_url), + ), + exit_code: Some(r.exit_code), + termination: CommandTermination::Exited, + duration_ms: 0, + }, ); tracing::warn!( error = %err, diff --git a/lib/crates/fabro-sandbox/src/error.rs b/lib/crates/fabro-sandbox/src/error.rs index 2b7ae5ae2..2b84d190b 100644 --- a/lib/crates/fabro-sandbox/src/error.rs +++ b/lib/crates/fabro-sandbox/src/error.rs @@ -1,6 +1,5 @@ #[cfg(feature = "docker")] use bollard::errors::Error as BollardError; -use fabro_types::CommandTermination; use fabro_util::error::{collect_causes, render_with_causes}; #[derive(Debug, thiserror::Error)] @@ -40,18 +39,16 @@ pub enum Error { #[error( "{label} failed (exit {exit}, termination={termination}, duration_ms={duration_ms}) - hint: {hint}", - exit = format_exit_code(*exit_code), - hint = classify_exec_failure(stderr) - .or_else(|| classify_exec_failure(stdout)) + exit = format_exit_code(result.exit_code), + termination = result.termination, + duration_ms = result.duration_ms, + hint = classify_exec_failure(&result.stderr) + .or_else(|| classify_exec_failure(&result.stdout)) .unwrap_or("unclassified") )] Exec { - label: String, - exit_code: Option, - termination: CommandTermination, - duration_ms: u64, - stderr: String, - stdout: String, + label: String, + result: crate::ExecResult, }, } @@ -70,24 +67,25 @@ impl Error { } } - pub fn exec( - label: impl Into, - exit_code: Option, - termination: CommandTermination, - duration_ms: u64, - stderr: impl Into, - stdout: impl Into, - ) -> Self { + pub fn exec(label: impl Into, result: crate::ExecResult) -> Self { Self::Exec { label: label.into(), - exit_code, - termination, - duration_ms, - stderr: stderr.into(), - stdout: stdout.into(), + result, } } + pub fn exec_result(&self) -> Option<&crate::ExecResult> { + match self { + Self::Exec { result, .. } => Some(result), + _ => None, + } + } + + pub fn default_redacted_output_tail(&self) -> Option { + self.exec_result() + .and_then(crate::ExecResult::default_redacted_output_tail) + } + #[cfg(feature = "docker")] pub fn docker_connect(source: BollardError) -> Self { Self::DockerConnect { source } @@ -172,6 +170,8 @@ pub type Result = std::result::Result; #[cfg(test)] mod tests { + use fabro_types::CommandTermination; + use super::*; #[test] @@ -180,16 +180,46 @@ mod tests { 'https://x-access-token:ghs_xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA@github.com/owner/repo/':\n\ remote: Permission to owner/repo.git denied\n\ identity ~/.ssh/id_rsa_work"; - let error = Error::exec( - "git push origin refs/heads/run", - Some(128), - CommandTermination::Exited, - 210, - stderr, - "", - ); + let error = Error::exec("git push origin refs/heads/run", crate::ExecResult { + stdout: String::new(), + stderr: stderr.to_string(), + exit_code: Some(128), + termination: CommandTermination::Exited, + duration_ms: 210, + }); let rendered = error.to_string(); + assert_exec_rendering_is_safe(&rendered); + assert!(rendered.contains("git push origin refs/heads/run")); + assert!(rendered.contains("exit 128")); + assert!(rendered.contains("termination=exited")); + assert!(rendered.contains("duration_ms=210")); + assert!(rendered.contains("hint:")); + } + + #[test] + fn display_with_causes_does_not_reintroduce_raw_exec_output() { + let stderr = "fatal: unable to access \ + 'https://x-access-token:ghs_xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA@github.com/owner/repo/':\n\ + remote: Permission to owner/repo.git denied\n\ + identity ~/.ssh/id_rsa_work"; + let exec_error = Error::exec("git push origin refs/heads/run", crate::ExecResult { + stdout: "stdout secret ghs_xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA".to_string(), + stderr: stderr.to_string(), + exit_code: Some(128), + termination: CommandTermination::Exited, + duration_ms: 210, + }); + let error = Error::context("metadata push failed", exec_error); + let rendered = error.display_with_causes(); + + assert_exec_rendering_is_safe(&rendered); + assert!(rendered.contains("metadata push failed")); + assert!(rendered.contains("git push origin refs/heads/run")); + assert!(rendered.contains("hint:")); + } + + fn assert_exec_rendering_is_safe(rendered: &str) { for forbidden in [ "fatal:", "remote:", @@ -203,11 +233,27 @@ mod tests { "Display leaked {forbidden:?}: {rendered}" ); } - assert!(rendered.contains("git push origin refs/heads/run")); - assert!(rendered.contains("exit 128")); - assert!(rendered.contains("termination=exited")); - assert!(rendered.contains("duration_ms=210")); - assert!(rendered.contains("hint:")); + } + + #[test] + fn exec_error_exposes_default_redacted_output_tail() { + let stderr = "stderr secret ghs_xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA"; + let error = Error::exec("git push origin refs/heads/run", crate::ExecResult { + stdout: "last stdout line".to_string(), + stderr: stderr.to_string(), + exit_code: Some(128), + termination: CommandTermination::Exited, + duration_ms: 210, + }); + + let tail = error.default_redacted_output_tail().expect("tail present"); + assert_eq!(tail.stdout.as_deref(), Some("last stdout line")); + assert!( + tail.stderr + .as_deref() + .expect("stderr tail") + .contains("REDACTED") + ); } #[test] diff --git a/lib/crates/fabro-sandbox/src/sandbox.rs b/lib/crates/fabro-sandbox/src/sandbox.rs index d2c26751b..0a7e39619 100644 --- a/lib/crates/fabro-sandbox/src/sandbox.rs +++ b/lib/crates/fabro-sandbox/src/sandbox.rs @@ -15,6 +15,8 @@ use tokio_util::sync::CancellationToken; /// Git command prefix that disables background maintenance. const GIT: &str = "git -c maintenance.auto=0 -c gc.auto=0"; +pub const DEFAULT_EXEC_OUTPUT_TAIL_BYTES: usize = 8 * 1024; + /// Information returned when a sandbox sets up git for a workflow run. #[derive(Debug, Clone)] pub struct GitRunInfo { @@ -422,14 +424,7 @@ impl ExecResult { } pub fn into_exec_error(self, label: impl Into) -> crate::Error { - crate::Error::exec( - label, - self.exit_code, - self.termination, - self.duration_ms, - self.stderr, - self.stdout, - ) + crate::Error::exec(label, self) } pub fn into_exec_error_with_redactor( @@ -437,16 +432,11 @@ impl ExecResult { label: impl Into, redactor: impl Fn(&str) -> String, ) -> crate::Error { - let stderr = redactor(&self.stderr); - let stdout = redactor(&self.stdout); - crate::Error::exec( - label, - self.exit_code, - self.termination, - self.duration_ms, - stderr, - stdout, - ) + crate::Error::exec(label, Self { + stdout: redactor(&self.stdout), + stderr: redactor(&self.stderr), + ..self + }) } pub fn into_result(self, label: impl Into) -> crate::Result { @@ -456,6 +446,115 @@ impl ExecResult { Err(self.into_exec_error(label)) } } + + pub fn redacted_output_tail( + &self, + max_bytes_per_stream: usize, + ) -> Option { + let (stdout, stdout_truncated) = redacted_tail(&self.stdout, max_bytes_per_stream); + let (stderr, stderr_truncated) = redacted_tail(&self.stderr, max_bytes_per_stream); + let tail = fabro_types::ExecOutputTail { + stdout, + stderr, + stdout_truncated, + stderr_truncated, + }; + (!tail.is_empty()).then_some(tail) + } + + pub fn default_redacted_output_tail(&self) -> Option { + self.redacted_output_tail(DEFAULT_EXEC_OUTPUT_TAIL_BYTES) + } + + /// Converts host process output into the canonical full exec result. + /// + /// This stores raw stdout/stderr. Callers must not log these fields + /// directly; use `default_redacted_output_tail()` for events and + /// tracing metadata. + pub fn from_process_output(output: std::process::Output, duration_ms: u64) -> Self { + let std::process::Output { + status, + stdout, + stderr, + } = output; + Self { + stdout: String::from_utf8_lossy(&stdout).into_owned(), + stderr: String::from_utf8_lossy(&stderr).into_owned(), + exit_code: Some(status.code().unwrap_or(-1)), + termination: CommandTermination::Exited, + duration_ms, + } + } +} + +fn redacted_tail(text: &str, max_bytes: usize) -> (Option, bool) { + if text.is_empty() || max_bytes == 0 { + return (None, !text.is_empty()); + } + + let redacted = fabro_redact::redact_string(text); + let sanitized = sanitize_exec_output(&redacted); + let truncated = sanitized.len() > max_bytes; + let start = if truncated { + floor_char_boundary(&sanitized, sanitized.len() - max_bytes) + } else { + 0 + }; + let tail = sanitized[start..].to_string(); + ((!tail.is_empty()).then_some(tail), truncated) +} + +fn sanitize_exec_output(text: &str) -> String { + let mut sanitized = String::with_capacity(text.len()); + let mut chars = text.chars().peekable(); + while let Some(ch) = chars.next() { + if ch == '\u{1b}' { + match chars.peek().copied() { + Some('[') => { + chars.next(); + for next in chars.by_ref() { + if ('@'..='~').contains(&next) { + break; + } + } + } + Some(']') => { + chars.next(); + let mut saw_esc = false; + for next in chars.by_ref() { + if next == '\u{7}' || (saw_esc && next == '\\') { + break; + } + saw_esc = next == '\u{1b}'; + } + } + Some('(' | ')' | '*' | '+' | '-' | '.' | '/') => { + chars.next(); + chars.next(); + } + Some('@'..='_') => { + chars.next(); + } + _ => {} + } + continue; + } + if ch == '\n' || ch == '\r' || ch == '\t' || !ch.is_control() { + sanitized.push(ch); + } + } + sanitized +} + +fn floor_char_boundary(text: &str, index: usize) -> usize { + if index >= text.len() { + return text.len(); + } + let mut boundary = index; + while boundary > 0 && !text.is_char_boundary(boundary) { + boundary -= 1; + } + boundary } #[derive(Debug, Clone)] @@ -841,14 +940,11 @@ mod tests { duration_ms: 42, }; let error = result.into_result("git push").unwrap_err(); - let crate::Error::Exec { - label, exit_code, .. - } = &error - else { + let crate::Error::Exec { label, result, .. } = &error else { panic!("expected Error::Exec, got {error:?}"); }; assert_eq!(label, "git push"); - assert_eq!(*exit_code, Some(128)); + assert_eq!(result.exit_code, Some(128)); assert!(error.to_string().contains("no credentials in origin URL")); } @@ -884,11 +980,123 @@ mod tests { s.replace("https://token@example.com", "https://****@example.com") }); - let crate::Error::Exec { stderr, stdout, .. } = &error else { + let crate::Error::Exec { result, .. } = &error else { panic!("expected Error::Exec, got {error:?}"); }; - assert_eq!(stderr, "stderr https://****@example.com"); - assert_eq!(stdout, "stdout https://****@example.com"); + assert_eq!(result.stderr, "stderr https://****@example.com"); + assert_eq!(result.stdout, "stdout https://****@example.com"); + } + + #[test] + fn exec_result_redacts_before_taking_tail() { + let secret = "sk-ant-api03-xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA"; + let result = ExecResult { + stdout: format!("{} {secret} done", "context ".repeat(20)), + stderr: String::new(), + exit_code: Some(1), + termination: CommandTermination::Exited, + duration_ms: 1, + }; + + let tail = result + .redacted_output_tail(32) + .expect("redacted output tail"); + let stdout = tail.stdout.expect("stdout tail"); + assert!(stdout.contains("REDACTED"), "{stdout}"); + assert!(!stdout.contains("F0gH3jE6pA"), "{stdout}"); + assert!(tail.stdout_truncated); + } + + #[test] + fn exec_result_tail_sanitizes_terminal_control_sequences() { + let result = ExecResult { + stdout: "\u{1b}[31mred\u{1b}[0m \u{1b}]0;window-title\u{7}shown \ + \u{1b}(Bset \u{1b}Mtwo-byte \u{8}backspace" + .to_string(), + stderr: String::new(), + exit_code: Some(1), + termination: CommandTermination::Exited, + duration_ms: 1, + }; + + let tail = result + .redacted_output_tail(1024) + .expect("redacted output tail"); + let stdout = tail.stdout.expect("stdout tail"); + assert_eq!(stdout, "red shown set two-byte backspace"); + } + + #[cfg(unix)] + #[test] + #[expect( + clippy::disallowed_methods, + reason = "test intentionally creates host process output for conversion coverage" + )] + fn from_process_output_uses_minus_one_for_signal_exit_without_code() { + let output = std::process::Command::new("sh") + .arg("-c") + .arg("printf out; printf err >&2; kill -9 $$") + .output() + .expect("signal-killed process output"); + + let result = ExecResult::from_process_output(output, 12); + + assert_eq!(result.stdout, "out"); + assert_eq!(result.stderr, "err"); + assert_eq!(result.exit_code, Some(-1)); + assert_eq!(result.termination, CommandTermination::Exited); + assert_eq!(result.duration_ms, 12); + } + + #[cfg(unix)] + #[test] + #[expect( + clippy::disallowed_methods, + reason = "test intentionally creates host process output for conversion coverage" + )] + fn from_process_output_handles_lossy_non_utf8_output() { + let output = std::process::Command::new("sh") + .arg("-c") + .arg("printf '\\377'; printf '\\376' >&2") + .output() + .expect("non-utf8 process output"); + + let result = ExecResult::from_process_output(output, 3); + let tail = result + .redacted_output_tail(16) + .expect("redacted output tail"); + + assert!(tail.stdout.expect("stdout tail").len() <= 16); + assert!(tail.stderr.expect("stderr tail").len() <= 16); + } + + #[test] + fn default_exec_output_tail_serialized_budget_stays_below_40_kib() { + let result = ExecResult { + stdout: "o".repeat(DEFAULT_EXEC_OUTPUT_TAIL_BYTES + 128), + stderr: "e".repeat(DEFAULT_EXEC_OUTPUT_TAIL_BYTES + 128), + exit_code: Some(1), + termination: CommandTermination::Exited, + duration_ms: 1, + }; + + let tail = result.default_redacted_output_tail().expect("tail present"); + assert_eq!( + tail.stdout.as_deref().map(str::len), + Some(DEFAULT_EXEC_OUTPUT_TAIL_BYTES) + ); + assert_eq!( + tail.stderr.as_deref().map(str::len), + Some(DEFAULT_EXEC_OUTPUT_TAIL_BYTES) + ); + assert!(tail.stdout_truncated); + assert!(tail.stderr_truncated); + let serialized = serde_json::to_vec(&tail).expect("serialize tail"); + assert!( + serialized.len() < 40 * 1024, + "tail JSON was {} bytes", + serialized.len() + ); } #[test] diff --git a/lib/crates/fabro-types/src/lib.rs b/lib/crates/fabro-types/src/lib.rs index dd2e4b87b..10fc1816c 100644 --- a/lib/crates/fabro-types/src/lib.rs +++ b/lib/crates/fabro-types/src/lib.rs @@ -69,7 +69,7 @@ pub use run::{ }; pub use run_blob_id::RunBlobId; pub use run_event::{ - ActorKind, ActorRef, EventBody, InterviewOption, MetadataSnapshotFailureKind, + ActorKind, ActorRef, EventBody, ExecOutputTail, InterviewOption, MetadataSnapshotFailureKind, MetadataSnapshotPhase, RunEvent, RunNoticeLevel, }; pub use run_id::{RunId, fixtures}; diff --git a/lib/crates/fabro-types/src/run_event/infra.rs b/lib/crates/fabro-types/src/run_event/infra.rs index 3dc726b77..20d332149 100644 --- a/lib/crates/fabro-types/src/run_event/infra.rs +++ b/lib/crates/fabro-types/src/run_event/infra.rs @@ -54,6 +54,44 @@ pub enum MetadataSnapshotFailureKind { Push, } +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +pub struct ExecOutputTail { + #[serde(default, skip_serializing_if = "Option::is_none")] + pub stdout: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub stderr: Option, + #[serde(default, skip_serializing_if = "is_false")] + pub stdout_truncated: bool, + #[serde(default, skip_serializing_if = "is_false")] + pub stderr_truncated: bool, +} + +#[allow( + clippy::trivially_copy_pass_by_ref, + reason = "serde skip_serializing_if predicates receive fields by reference" +)] +fn is_false(value: &bool) -> bool { + !*value +} + +impl ExecOutputTail { + #[must_use] + pub fn is_empty(&self) -> bool { + self.stdout.as_deref().unwrap_or("").is_empty() + && self.stderr.as_deref().unwrap_or("").is_empty() + } + + #[must_use] + pub fn stdout_len(&self) -> usize { + self.stdout.as_deref().map_or(0, str::len) + } + + #[must_use] + pub fn stderr_len(&self) -> usize { + self.stderr.as_deref().map_or(0, str::len) + } +} + #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] pub struct MetadataSnapshotStartedProps { pub phase: MetadataSnapshotPhase, @@ -72,19 +110,21 @@ pub struct MetadataSnapshotCompletedProps { #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] pub struct MetadataSnapshotFailedProps { - pub phase: MetadataSnapshotPhase, - pub branch: String, - pub duration_ms: u64, - pub failure_kind: MetadataSnapshotFailureKind, - pub error: String, + pub phase: MetadataSnapshotPhase, + pub branch: String, + pub duration_ms: u64, + pub failure_kind: MetadataSnapshotFailureKind, + pub error: String, #[serde(default, skip_serializing_if = "Vec::is_empty")] - pub causes: Vec, + pub causes: Vec, #[serde(default, skip_serializing_if = "Option::is_none")] - pub commit_sha: Option, + pub commit_sha: Option, #[serde(default, skip_serializing_if = "Option::is_none")] - pub entry_count: Option, + pub entry_count: Option, #[serde(default, skip_serializing_if = "Option::is_none")] - pub bytes: Option, + pub bytes: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub exec_output_tail: Option, } #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] @@ -214,10 +254,12 @@ pub struct SetupCompletedProps { #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] pub struct SetupFailedProps { - pub command: String, - pub index: usize, - pub exit_code: i32, - pub stderr: String, + pub command: String, + pub index: usize, + pub exit_code: i32, + pub stderr: String, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub exec_output_tail: Option, } #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] @@ -237,10 +279,12 @@ pub struct CliEnsureCompletedProps { #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] pub struct CliEnsureFailedProps { - pub cli_name: String, - pub provider: String, - pub error: String, - pub duration_ms: u64, + pub cli_name: String, + pub provider: String, + pub error: String, + pub duration_ms: u64, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub exec_output_tail: Option, } #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] @@ -281,9 +325,11 @@ pub struct DevcontainerLifecycleCompletedProps { #[derive(Debug, Clone, PartialEq, Serialize, Deserialize)] pub struct DevcontainerLifecycleFailedProps { - pub phase: String, - pub command: String, - pub index: usize, - pub exit_code: i32, - pub stderr: String, + pub phase: String, + pub command: String, + pub index: usize, + pub exit_code: i32, + pub stderr: String, + #[serde(default, skip_serializing_if = "Option::is_none")] + pub exec_output_tail: Option, } diff --git a/lib/crates/fabro-types/src/run_event/mod.rs b/lib/crates/fabro-types/src/run_event/mod.rs index 30552b2df..8cd8412c4 100644 --- a/lib/crates/fabro-types/src/run_event/mod.rs +++ b/lib/crates/fabro-types/src/run_event/mod.rs @@ -1281,15 +1281,16 @@ mod tests { #[test] fn metadata_snapshot_failed_omits_empty_optional_fields() { let body = EventBody::MetadataSnapshotFailed(MetadataSnapshotFailedProps { - phase: MetadataSnapshotPhase::Init, - branch: "fabro/metadata/run".to_string(), - duration_ms: 15, - failure_kind: MetadataSnapshotFailureKind::LoadState, - error: "state unavailable".to_string(), - causes: Vec::new(), - commit_sha: None, - entry_count: None, - bytes: None, + phase: MetadataSnapshotPhase::Init, + branch: "fabro/metadata/run".to_string(), + duration_ms: 15, + failure_kind: MetadataSnapshotFailureKind::LoadState, + error: "state unavailable".to_string(), + causes: Vec::new(), + commit_sha: None, + entry_count: None, + bytes: None, + exec_output_tail: None, }); let value = serde_json::to_value(&body).unwrap(); @@ -1305,4 +1306,67 @@ mod tests { }) ); } + + #[test] + fn metadata_snapshot_failed_serializes_exec_output_tail_additively() { + let body = EventBody::MetadataSnapshotFailed(MetadataSnapshotFailedProps { + phase: MetadataSnapshotPhase::Checkpoint, + branch: "fabro/metadata/run".to_string(), + duration_ms: 20, + failure_kind: MetadataSnapshotFailureKind::Push, + error: "push failed".to_string(), + causes: Vec::new(), + commit_sha: None, + entry_count: None, + bytes: None, + exec_output_tail: Some(ExecOutputTail { + stdout: Some("last stdout line".to_string()), + stderr: Some("last stderr line".to_string()), + stdout_truncated: false, + stderr_truncated: true, + }), + }); + + let value = serde_json::to_value(&body).unwrap(); + assert_eq!( + value["properties"]["exec_output_tail"]["stdout"], + "last stdout line" + ); + assert_eq!( + value["properties"]["exec_output_tail"]["stderr"], + "last stderr line" + ); + assert_eq!( + value["properties"]["exec_output_tail"]["stderr_truncated"], + true + ); + assert!( + value["properties"]["exec_output_tail"] + .as_object() + .expect("exec output tail object") + .get("stdout_truncated") + .is_none() + ); + + let body_without_tail = EventBody::MetadataSnapshotFailed(MetadataSnapshotFailedProps { + phase: MetadataSnapshotPhase::Checkpoint, + branch: "fabro/metadata/run".to_string(), + duration_ms: 20, + failure_kind: MetadataSnapshotFailureKind::Push, + error: "push failed".to_string(), + causes: Vec::new(), + commit_sha: None, + entry_count: None, + bytes: None, + exec_output_tail: None, + }); + let value_without_tail = serde_json::to_value(&body_without_tail).unwrap(); + assert!( + value_without_tail["properties"] + .as_object() + .expect("properties object") + .get("exec_output_tail") + .is_none() + ); + } } diff --git a/lib/crates/fabro-workflow/src/devcontainer_bridge.rs b/lib/crates/fabro-workflow/src/devcontainer_bridge.rs index c70a37585..36e73002c 100644 --- a/lib/crates/fabro-workflow/src/devcontainer_bridge.rs +++ b/lib/crates/fabro-workflow/src/devcontainer_bridge.rs @@ -124,6 +124,7 @@ pub async fn run_devcontainer_lifecycle( let cmd_duration = crate::millis_u64(cmd_start.elapsed()); if !result.is_success() { let exit_code = result.display_exit_code(); + let exec_output_tail = result.default_redacted_output_tail(); emitter.emit( &Event::DevcontainerLifecycleFailed { phase: phase.clone(), @@ -131,6 +132,7 @@ pub async fn run_devcontainer_lifecycle( index, exit_code, stderr: result.stderr.clone(), + exec_output_tail, }, ); return Err(Error::engine(format!( @@ -195,12 +197,14 @@ async fn run_single_lifecycle_command( let cmd_duration = crate::millis_u64(cmd_start.elapsed()); if !result.is_success() { let exit_code = result.display_exit_code(); + let exec_output_tail = result.default_redacted_output_tail(); emitter.emit(&Event::DevcontainerLifecycleFailed { phase: phase.to_string(), command: command.to_string(), index, exit_code, stderr: result.stderr.clone(), + exec_output_tail, }); return Err(Error::engine(format!( "Devcontainer {phase} command failed (exit code {}): {command}\n{}", @@ -226,7 +230,7 @@ mod tests { use async_trait::async_trait; use fabro_agent::sandbox::{ExecResult, GrepOptions, Sandbox}; - use fabro_types::CommandTermination; + use fabro_types::{CommandTermination, EventBody}; use tokio_util::sync::CancellationToken; use super::*; @@ -514,12 +518,25 @@ mod tests { .await; assert!(result.is_err()); let events = events.lock().unwrap(); - assert!(events.iter().any(|event| { - event.event_name() == "devcontainer.lifecycle.failed" - && event.properties().is_ok_and(|properties| { - properties["phase"] == "on_create" && properties["exit_code"] == 1 - }) - })); + let failed = events + .iter() + .find(|event| event.event_name() == "devcontainer.lifecycle.failed") + .expect("devcontainer lifecycle failed event"); + match &failed.body { + EventBody::DevcontainerLifecycleFailed(props) => { + assert_eq!(props.phase, "on_create"); + assert_eq!(props.exit_code, 1); + assert_eq!(props.stderr, "command failed"); + assert_eq!( + props + .exec_output_tail + .as_ref() + .and_then(|tail| tail.stderr.as_deref()), + Some("command failed") + ); + } + other => panic!("expected devcontainer lifecycle failed body, got {other:?}"), + } } #[tokio::test] diff --git a/lib/crates/fabro-workflow/src/event.rs b/lib/crates/fabro-workflow/src/event.rs index 084a2e969..6b98d0bde 100644 --- a/lib/crates/fabro-workflow/src/event.rs +++ b/lib/crates/fabro-workflow/src/event.rs @@ -159,19 +159,21 @@ pub enum Event { commit_sha: String, }, MetadataSnapshotFailed { - phase: fabro_types::MetadataSnapshotPhase, - branch: String, - duration_ms: u64, - failure_kind: fabro_types::MetadataSnapshotFailureKind, - error: String, + phase: fabro_types::MetadataSnapshotPhase, + branch: String, + duration_ms: u64, + failure_kind: fabro_types::MetadataSnapshotFailureKind, + error: String, #[serde(default, skip_serializing_if = "Vec::is_empty")] - causes: Vec, + causes: Vec, #[serde(default, skip_serializing_if = "Option::is_none")] - commit_sha: Option, + commit_sha: Option, #[serde(default, skip_serializing_if = "Option::is_none")] - entry_count: Option, + entry_count: Option, #[serde(default, skip_serializing_if = "Option::is_none")] - bytes: Option, + bytes: Option, + #[serde(default, skip_serializing_if = "Option::is_none")] + exec_output_tail: Option, }, StageStarted { node_id: String, @@ -443,10 +445,12 @@ pub enum Event { duration_ms: u64, }, SetupFailed { - command: String, - index: usize, - exit_code: i32, - stderr: String, + command: String, + index: usize, + exit_code: i32, + stderr: String, + #[serde(default, skip_serializing_if = "Option::is_none")] + exec_output_tail: Option, }, StallWatchdogTimeout { node: String, @@ -485,10 +489,12 @@ pub enum Event { duration_ms: u64, }, CliEnsureFailed { - cli_name: String, - provider: String, - error: String, - duration_ms: u64, + cli_name: String, + provider: String, + error: String, + duration_ms: u64, + #[serde(default, skip_serializing_if = "Option::is_none")] + exec_output_tail: Option, }, CommandStarted { node_id: String, @@ -566,11 +572,13 @@ pub enum Event { duration_ms: u64, }, DevcontainerLifecycleFailed { - phase: String, - command: String, - index: usize, - exit_code: i32, - stderr: String, + phase: String, + command: String, + index: usize, + exit_code: i32, + stderr: String, + #[serde(default, skip_serializing_if = "Option::is_none")] + exec_output_tail: Option, }, RetroStarted { #[serde(default, skip_serializing_if = "Option::is_none")] @@ -727,6 +735,7 @@ impl Event { duration_ms, failure_kind, error, + exec_output_tail, .. } => { warn!( @@ -735,6 +744,19 @@ impl Event { duration_ms, %failure_kind, error, + exec_output_tail_present = exec_output_tail.is_some(), + exec_stdout_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stdout_len), + exec_stderr_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stderr_len), + exec_stdout_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stdout_truncated), + exec_stderr_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stderr_truncated), "Metadata snapshot failed" ); } @@ -1032,9 +1054,28 @@ impl Event { command, index, exit_code, + exec_output_tail, .. } => { - error!(command, index, exit_code, "Setup command failed"); + error!( + command, + index, + exit_code, + exec_output_tail_present = exec_output_tail.is_some(), + exec_stdout_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stdout_len), + exec_stderr_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stderr_len), + exec_stdout_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stdout_truncated), + exec_stderr_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stderr_truncated), + "Setup command failed" + ); } Self::StallWatchdogTimeout { node, idle_seconds } => { warn!(node, idle_seconds, "Stall watchdog timeout"); @@ -1099,8 +1140,28 @@ impl Event { provider, error, duration_ms, + exec_output_tail, } => { - error!(cli_name, provider, error, duration_ms, "CLI ensure failed"); + error!( + cli_name, + provider, + error, + duration_ms, + exec_output_tail_present = exec_output_tail.is_some(), + exec_stdout_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stdout_len), + exec_stderr_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stderr_len), + exec_stdout_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stdout_truncated), + exec_stderr_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stderr_truncated), + "CLI ensure failed" + ); } Self::CommandStarted { node_id, @@ -1212,11 +1273,28 @@ impl Event { command, index, exit_code, + exec_output_tail, .. } => { error!( phase, - command, index, exit_code, "Devcontainer lifecycle command failed" + command, + index, + exit_code, + exec_output_tail_present = exec_output_tail.is_some(), + exec_stdout_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stdout_len), + exec_stderr_tail_bytes = exec_output_tail + .as_ref() + .map_or(0, fabro_types::ExecOutputTail::stderr_len), + exec_stdout_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stdout_truncated), + exec_stderr_truncated = exec_output_tail + .as_ref() + .is_some_and(|tail| tail.stderr_truncated), + "Devcontainer lifecycle command failed" ); } Self::RetroStarted { @@ -1762,16 +1840,18 @@ fn event_body_from_event(event: &Event) -> EventBody { commit_sha, entry_count, bytes, + exec_output_tail, } => EventBody::MetadataSnapshotFailed(fabro_types::MetadataSnapshotFailedProps { - phase: *phase, - branch: branch.clone(), - duration_ms: *duration_ms, - failure_kind: *failure_kind, - error: error.clone(), - causes: causes.clone(), - commit_sha: commit_sha.clone(), - entry_count: *entry_count, - bytes: *bytes, + phase: *phase, + branch: branch.clone(), + duration_ms: *duration_ms, + failure_kind: *failure_kind, + error: error.clone(), + causes: causes.clone(), + commit_sha: commit_sha.clone(), + entry_count: *entry_count, + bytes: *bytes, + exec_output_tail: exec_output_tail.clone(), }), Event::StageStarted { index, @@ -2402,11 +2482,13 @@ fn event_body_from_event(event: &Event) -> EventBody { index, exit_code, stderr, + exec_output_tail, } => EventBody::SetupFailed(fabro_types::SetupFailedProps { - command: command.clone(), - index: *index, - exit_code: *exit_code, - stderr: stderr.clone(), + command: command.clone(), + index: *index, + exit_code: *exit_code, + stderr: stderr.clone(), + exec_output_tail: exec_output_tail.clone(), }), Event::StallWatchdogTimeout { idle_seconds, .. } => { EventBody::StallWatchdogTimeout(fabro_types::StallWatchdogTimeoutProps { @@ -2474,11 +2556,13 @@ fn event_body_from_event(event: &Event) -> EventBody { provider, error, duration_ms, + exec_output_tail, } => EventBody::CliEnsureFailed(fabro_types::CliEnsureFailedProps { - cli_name: cli_name.clone(), - provider: provider.clone(), - error: error.clone(), - duration_ms: *duration_ms, + cli_name: cli_name.clone(), + provider: provider.clone(), + error: error.clone(), + duration_ms: *duration_ms, + exec_output_tail: exec_output_tail.clone(), }), Event::CommandStarted { script, @@ -2624,13 +2708,15 @@ fn event_body_from_event(event: &Event) -> EventBody { index, exit_code, stderr, + exec_output_tail, } => { EventBody::DevcontainerLifecycleFailed(fabro_types::DevcontainerLifecycleFailedProps { - phase: phase.clone(), - command: command.clone(), - index: *index, - exit_code: *exit_code, - stderr: stderr.clone(), + phase: phase.clone(), + command: command.clone(), + index: *index, + exit_code: *exit_code, + stderr: stderr.clone(), + exec_output_tail: exec_output_tail.clone(), }) } Event::RetroStarted { @@ -3494,6 +3580,34 @@ mod tests { ); } + #[test] + fn build_redacted_event_payload_redacts_exec_output_tail_values() { + let secret = "sk-ant-api03-xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA"; + let stored = to_run_event(&fixtures::RUN_8, &Event::SetupFailed { + command: "setup".to_string(), + index: 0, + exit_code: 1, + stderr: "compat stderr".to_string(), + exec_output_tail: Some(fabro_types::ExecOutputTail { + stdout: Some(format!("stdout {secret}")), + stderr: Some("plain stderr".to_string()), + stdout_truncated: false, + stderr_truncated: false, + }), + }); + + let payload = build_redacted_event_payload(&stored, &fixtures::RUN_8).unwrap(); + let payload_text = serde_json::to_string(payload.as_value()).unwrap(); + + assert!(!payload_text.contains(secret)); + assert!(payload_text.contains("REDACTED")); + assert_eq!(payload.as_value()["event"], "setup.failed"); + assert_eq!( + payload.as_value()["properties"]["exec_output_tail"]["stderr"], + "plain stderr" + ); + } + #[test] fn event_name_matches_new_dot_notation() { assert_eq!( @@ -3793,15 +3907,21 @@ mod tests { } let failed = to_run_event(&fixtures::RUN_1, &Event::MetadataSnapshotFailed { - phase: fabro_types::MetadataSnapshotPhase::Checkpoint, - branch: "fabro/metadata/run".to_string(), - duration_ms: 120, - failure_kind: fabro_types::MetadataSnapshotFailureKind::Push, - error: "push rejected".to_string(), - causes: vec!["permission denied".to_string()], - commit_sha: Some("def456".to_string()), - entry_count: Some(4), - bytes: Some(512), + phase: fabro_types::MetadataSnapshotPhase::Checkpoint, + branch: "fabro/metadata/run".to_string(), + duration_ms: 120, + failure_kind: fabro_types::MetadataSnapshotFailureKind::Push, + error: "push rejected".to_string(), + causes: vec!["permission denied".to_string()], + commit_sha: Some("def456".to_string()), + entry_count: Some(4), + bytes: Some(512), + exec_output_tail: Some(fabro_types::ExecOutputTail { + stdout: Some("last stdout line".to_string()), + stderr: Some("last stderr line".to_string()), + stdout_truncated: false, + stderr_truncated: true, + }), }); assert_eq!(failed.event_name(), "metadata.snapshot.failed"); @@ -3814,6 +3934,11 @@ mod tests { assert_eq!(props.commit_sha.as_deref(), Some("def456")); assert_eq!(props.entry_count, Some(4)); assert_eq!(props.bytes, Some(512)); + let tail = props.exec_output_tail.expect("exec output tail"); + assert_eq!(tail.stdout.as_deref(), Some("last stdout line")); + assert_eq!(tail.stderr.as_deref(), Some("last stderr line")); + assert!(tail.stderr_truncated); + assert!(!tail.stdout_truncated); } other => panic!("expected MetadataSnapshotFailed body, got {other:?}"), } diff --git a/lib/crates/fabro-workflow/src/handler/llm/cli.rs b/lib/crates/fabro-workflow/src/handler/llm/cli.rs index d9ecb34e4..e7dd6a733 100644 --- a/lib/crates/fabro-workflow/src/handler/llm/cli.rs +++ b/lib/crates/fabro-workflow/src/handler/llm/cli.rs @@ -117,21 +117,9 @@ async fn ensure_cli( let node_installed = true; if !install_result.is_success() { let duration_ms = elapsed_ms(start); - let output = if install_result.stderr.is_empty() { - &install_result.stdout - } else { - &install_result.stderr - }; - let detail: String = output - .chars() - .rev() - .take(500) - .collect::>() - .into_iter() - .rev() - .collect(); + let exec_output_tail = install_result.default_redacted_output_tail(); let error_msg = format!( - "{cli_name} install exited with code {}: {detail}", + "{cli_name} install exited with code {}", install_result.display_exit_code() ); emitter.emit(&Event::CliEnsureFailed { @@ -139,6 +127,7 @@ async fn ensure_cli( provider: provider_str.to_string(), error: error_msg.clone(), duration_ms, + exec_output_tail, }); return Err(Error::handler(error_msg)); } @@ -986,11 +975,15 @@ mod tests { } fn fail_result(code: i32) -> ExecResult { + fail_result_with_output(code, "", "error") + } + + fn fail_result_with_output(code: i32, stdout: &str, stderr: &str) -> ExecResult { ExecResult { exit_code: Some(code), termination: CommandTermination::Exited, - stdout: String::new(), - stderr: "error".to_string(), + stdout: stdout.to_string(), + stderr: stderr.to_string(), duration_ms: 10, } } @@ -1039,20 +1032,49 @@ mod tests { let sandbox: Arc = Arc::new(CliMockSandbox::new( vec![ fail_result(127), // claude --version - fail_result(1), // combined install fails + fail_result_with_output(1, "install stdout detail", "install stderr detail"), ], Arc::clone(&commands), )); let emitter = Arc::new(Emitter::default()); + let events = Arc::new(Mutex::new(Vec::::new())); + emitter.on_event({ + let events = Arc::clone(&events); + move |event| events.lock().unwrap().push(event.clone()) + }); let result = ensure_cli(AgentCli::Claude, Provider::Anthropic, &sandbox, &emitter).await; assert!(result.is_err()); - assert!( - result - .unwrap_err() - .to_string() - .contains("install exited with code") - ); + let error = result.unwrap_err().to_string(); + assert!(error.contains("install exited with code 1")); + assert!(!error.contains("install stdout detail")); + assert!(!error.contains("install stderr detail")); + + let events = events.lock().unwrap(); + let failed = events + .iter() + .find(|event| event.event_name() == "cli.ensure.failed") + .expect("cli ensure failed event"); + match &failed.body { + fabro_types::EventBody::CliEnsureFailed(props) => { + assert_eq!(props.error, "claude install exited with code 1"); + assert_eq!( + props + .exec_output_tail + .as_ref() + .and_then(|tail| tail.stdout.as_deref()), + Some("install stdout detail") + ); + assert_eq!( + props + .exec_output_tail + .as_ref() + .and_then(|tail| tail.stderr.as_deref()), + Some("install stderr detail") + ); + } + other => panic!("expected cli ensure failed body, got {other:?}"), + } } // -- Cycle 1: cli_command_for_provider -- diff --git a/lib/crates/fabro-workflow/src/lifecycle/git.rs b/lib/crates/fabro-workflow/src/lifecycle/git.rs index b2cfaffe0..9593c0498 100644 --- a/lib/crates/fabro-workflow/src/lifecycle/git.rs +++ b/lib/crates/fabro-workflow/src/lifecycle/git.rs @@ -117,6 +117,7 @@ impl RunLifecycle for GitLifecycle { None, None, None, + None, ); self.emit_metadata_warning("checkpoint_metadata_write_failed", message); } @@ -185,6 +186,7 @@ impl RunLifecycle for GitLifecycle { None, None, None, + None, Some(&scope), ); self.emit_metadata_warning("checkpoint_metadata_write_failed", message); @@ -322,9 +324,11 @@ impl GitLifecycle { ); match writer.write_snapshot(dump, message).await { Ok(snapshot) => { - if let Some(detail) = snapshot.push_error.as_deref() { - let message = - format!("failed to push metadata ref refs/heads/{meta_branch}: {detail}"); + if let Some(push_error) = snapshot.push_error.as_ref() { + let message = format!( + "failed to push metadata ref refs/heads/{meta_branch}: {}", + push_error.message + ); self.emit_metadata_snapshot_failed( phase, meta_branch, @@ -335,6 +339,7 @@ impl GitLifecycle { Some(snapshot.commit_sha.clone()), Some(snapshot.entry_count), Some(snapshot.bytes), + push_error.exec_output_tail.clone(), scope, ); self.emit_metadata_warning("checkpoint_metadata_push_failed", message); @@ -361,6 +366,7 @@ impl GitLifecycle { None, None, None, + err.exec_output_tail(), scope, ); self.emit_metadata_warning("checkpoint_metadata_write_failed", message); @@ -420,6 +426,7 @@ impl GitLifecycle { commit_sha: Option, entry_count: Option, bytes: Option, + exec_output_tail: Option, scope: Option<&StageScope>, ) { self.emit_metadata_snapshot_event( @@ -433,6 +440,7 @@ impl GitLifecycle { commit_sha, entry_count, bytes, + exec_output_tail, }, scope, ); @@ -755,6 +763,14 @@ mod tests { assert!(props.commit_sha.as_ref().is_some_and(|sha| !sha.is_empty())); assert_eq!(props.entry_count, Some(expected_entry_count)); assert_eq!(props.bytes, Some(expected_bytes)); + assert!( + props + .exec_output_tail + .as_ref() + .and_then(|tail| tail.stderr.as_deref()) + .is_some_and(|stderr| stderr.contains("fatal:")), + "expected push stderr tail in metadata failure props: {props:?}" + ); } other => panic!("expected metadata failed event, got {other:?}"), } diff --git a/lib/crates/fabro-workflow/src/pipeline/finalize.rs b/lib/crates/fabro-workflow/src/pipeline/finalize.rs index 9f036cced..03db4c99f 100644 --- a/lib/crates/fabro-workflow/src/pipeline/finalize.rs +++ b/lib/crates/fabro-workflow/src/pipeline/finalize.rs @@ -181,6 +181,7 @@ pub async fn write_finalize_commit( None, None, None, + None, ); emit_metadata_warning(services, "checkpoint_metadata_write_failed", message); return; @@ -198,9 +199,11 @@ pub async fn write_finalize_commit( ); match writer.write_snapshot(&dump, "finalize run").await { Ok(snapshot) => { - if let Some(detail) = snapshot.push_error.as_deref() { - let message = - format!("failed to push metadata ref refs/heads/{meta_branch}: {detail}"); + if let Some(push_error) = snapshot.push_error.as_ref() { + let message = format!( + "failed to push metadata ref refs/heads/{meta_branch}: {}", + push_error.message + ); emit_metadata_snapshot_failed( services, phase, @@ -212,6 +215,7 @@ pub async fn write_finalize_commit( Some(snapshot.commit_sha.clone()), Some(snapshot.entry_count), Some(snapshot.bytes), + push_error.exec_output_tail.clone(), ); emit_metadata_warning(services, "checkpoint_metadata_push_failed", message); } else { @@ -231,6 +235,7 @@ pub async fn write_finalize_commit( None, None, None, + err.exec_output_tail(), ); emit_metadata_warning(services, "checkpoint_metadata_write_failed", message); } @@ -280,6 +285,7 @@ fn emit_metadata_snapshot_failed( commit_sha: Option, entry_count: Option, bytes: Option, + exec_output_tail: Option, ) { services.emitter.emit(&Event::MetadataSnapshotFailed { phase, @@ -291,6 +297,7 @@ fn emit_metadata_snapshot_failed( commit_sha, entry_count, bytes, + exec_output_tail, }); } diff --git a/lib/crates/fabro-workflow/src/pipeline/initialize.rs b/lib/crates/fabro-workflow/src/pipeline/initialize.rs index 8cce99cb8..f46a5022b 100644 --- a/lib/crates/fabro-workflow/src/pipeline/initialize.rs +++ b/lib/crates/fabro-workflow/src/pipeline/initialize.rs @@ -675,11 +675,13 @@ pub async fn initialize( let duration_ms = crate::millis_u64(cmd_start.elapsed()); if !result.is_success() { let exit_code = result.display_exit_code(); + let exec_output_tail = result.default_redacted_output_tail(); options.emitter.emit(&Event::SetupFailed { command: command.clone(), index, exit_code, stderr: result.stderr.clone(), + exec_output_tail, }); return Err(Error::engine(format!( "Setup command failed (exit code {}): {command}\n{}", @@ -761,7 +763,7 @@ mod tests { use fabro_sandbox::SandboxSpec; use fabro_sandbox::config::WorktreeMode; use fabro_store::Database; - use fabro_types::{RunId, WorkflowSettings, fixtures}; + use fabro_types::{EventBody, RunEvent, RunId, WorkflowSettings, fixtures}; use fabro_vault::{SecretType, Vault}; use object_store::memory::InMemory; use tokio::sync::RwLock as AsyncRwLock; @@ -887,6 +889,71 @@ mod tests { ) } + async fn initialize_with_setup_command( + command: &str, + ) -> (crate::error::Result, Vec) { + let temp = tempfile::tempdir().unwrap(); + let run_dir = temp.path().join("run"); + std::fs::create_dir_all(&run_dir).unwrap(); + let (graph, source) = simple_graph(); + let persisted = test_persisted(graph, source, &run_dir); + let emitter = Arc::new(crate::event::Emitter::new(test_run_id())); + let seen = Arc::new(std::sync::Mutex::new(Vec::new())); + emitter.on_event({ + let seen = Arc::clone(&seen); + move |event| seen.lock().unwrap().push(event.clone()) + }); + + let result = initialize(persisted, InitOptions { + run_id: test_run_id(), + run_store: { + let store = memory_store(); + let inner = store.create_run(&test_run_id()).await.unwrap(); + inner.into() + }, + dry_run: false, + emitter, + sandbox: SandboxSpec::Local { + working_directory: std::env::current_dir().unwrap(), + }, + llm: LlmSpec { + model: "test-model".to_string(), + provider: fabro_llm::Provider::Anthropic, + fallback_chain: Vec::new(), + mcp_servers: Vec::new(), + dry_run: true, + }, + interviewer: Arc::new(AutoApproveInterviewer), + lifecycle: crate::run_options::LifecycleOptions { + setup_commands: vec![command.to_string()], + setup_command_timeout_ms: 1_000, + devcontainer_phases: vec![], + }, + run_options: test_settings(&run_dir), + workflow_path: None, + workflow_bundle: None, + hooks: fabro_hooks::HookSettings { hooks: vec![] }, + sandbox_env: SandboxEnvSpec { + devcontainer_env: HashMap::new(), + toml_env: HashMap::new(), + github_permissions: None, + origin_url: None, + }, + vault: None, + devcontainer: None, + git: None, + worktree_mode: None, + run_control: None, + registry_override: None, + artifact_sink: None, + checkpoint: None, + seed_context: None, + }) + .await; + let events = seen.lock().unwrap().clone(); + (result, events) + } + #[tokio::test] async fn resolve_worktree_plan_uses_local_worktree_without_pre_run_git_context() { let temp = tempfile::tempdir().unwrap(); @@ -1141,6 +1208,49 @@ mod tests { ); } + #[tokio::test] + async fn initialize_setup_failure_preserves_stderr_and_adds_exec_tail() { + let (result, events) = + initialize_with_setup_command("printf setup-out; printf setup-err >&2; exit 7").await; + + assert!(result.is_err()); + let failed = events + .iter() + .find(|event| event.event_name() == "setup.failed") + .expect("setup failed event"); + match &failed.body { + EventBody::SetupFailed(props) => { + assert_eq!(props.exit_code, 7); + assert_eq!(props.stderr, "setup-err"); + let tail = props.exec_output_tail.as_ref().expect("exec output tail"); + assert_eq!(tail.stdout.as_deref(), Some("setup-out")); + assert_eq!(tail.stderr.as_deref(), Some("setup-err")); + } + other => panic!("expected setup failed body, got {other:?}"), + } + } + + #[tokio::test] + async fn initialize_setup_failure_with_stdout_only_adds_stdout_tail() { + let (result, events) = initialize_with_setup_command("printf setup-out; exit 5").await; + + assert!(result.is_err()); + let failed = events + .iter() + .find(|event| event.event_name() == "setup.failed") + .expect("setup failed event"); + match &failed.body { + EventBody::SetupFailed(props) => { + assert_eq!(props.exit_code, 5); + assert!(props.stderr.is_empty()); + let tail = props.exec_output_tail.as_ref().expect("exec output tail"); + assert_eq!(tail.stdout.as_deref(), Some("setup-out")); + assert!(tail.stderr.is_none()); + } + other => panic!("expected setup failed body, got {other:?}"), + } + } + #[tokio::test] async fn initialize_cancelled_setup_command_returns_cancelled() { let temp = tempfile::tempdir().unwrap(); diff --git a/lib/crates/fabro-workflow/src/sandbox_git.rs b/lib/crates/fabro-workflow/src/sandbox_git.rs index 5b6c1e3b2..1214d9cfa 100644 --- a/lib/crates/fabro-workflow/src/sandbox_git.rs +++ b/lib/crates/fabro-workflow/src/sandbox_git.rs @@ -1139,7 +1139,8 @@ mod tests { .unwrap_err(); assert!(err.starts_with("sandbox git unavailable:")); - assert!(err.contains("git missing")); + assert!(err.contains("exit 127")); + assert!(!err.contains("git missing")); } #[tokio::test] @@ -1361,7 +1362,7 @@ mod tests { .map(|(_, bytes)| u64::try_from(bytes.len()).unwrap_or(u64::MAX)) .sum::(); let snapshot = writer.write_snapshot(&dump, "checkpoint").await.unwrap(); - assert_eq!(snapshot.push_error, None); + assert!(snapshot.push_error.is_none()); assert_eq!(snapshot.entry_count, expected_entry_count); assert_eq!(snapshot.bytes, expected_bytes); let commit_sha = snapshot.commit_sha; @@ -1522,16 +1523,26 @@ mod tests { assert_eq!(snapshot.bytes, expected_bytes); let push_error = snapshot.push_error.unwrap(); - assert!(push_error.contains("git push origin")); - assert!(push_error.contains("hint:")); + assert!(push_error.message.contains("git push origin")); + assert!(push_error.message.contains("hint:")); assert!( - !push_error.contains("fatal:"), - "push error should be log-safe: {push_error}" + !push_error.message.contains("fatal:"), + "push error should be log-safe: {}", + push_error.message ); assert!( - !push_error.contains(missing_origin.to_str().unwrap()), - "push error should not include raw git stderr paths: {push_error}" + !push_error + .message + .contains(missing_origin.to_str().unwrap()), + "push error should not include raw git stderr paths: {}", + push_error.message ); + let stderr_tail = push_error + .exec_output_tail + .as_ref() + .and_then(|tail| tail.stderr.as_deref()) + .expect("push failure stderr tail"); + assert!(stderr_tail.contains("fatal:"), "{stderr_tail}"); } #[tokio::test] diff --git a/lib/crates/fabro-workflow/src/sandbox_metadata.rs b/lib/crates/fabro-workflow/src/sandbox_metadata.rs index 1d29051b8..34555e2eb 100644 --- a/lib/crates/fabro-workflow/src/sandbox_metadata.rs +++ b/lib/crates/fabro-workflow/src/sandbox_metadata.rs @@ -19,10 +19,22 @@ pub(crate) enum SandboxMetadataError { Dump(#[from] anyhow::Error), #[error("metadata temp file write failed: {0}")] LocalTemp(std::io::Error), - #[error("{0}")] - Git(String), - #[error("{0}")] - Sandbox(String), + #[error("{message}")] + Operation { + message: String, + exec_output_tail: Option, + }, +} + +impl SandboxMetadataError { + pub(crate) fn exec_output_tail(&self) -> Option { + match self { + Self::Operation { + exec_output_tail, .. + } => exec_output_tail.clone(), + _ => None, + } + } } pub(crate) struct SandboxGitRuntime { @@ -77,11 +89,17 @@ pub(crate) struct SandboxMetadataWriter<'a> { pub(crate) struct MetadataSnapshot { pub commit_sha: String, - pub push_error: Option, + pub push_error: Option, pub entry_count: usize, pub bytes: u64, } +#[derive(Debug, Clone)] +pub(crate) struct MetadataPushError { + pub message: String, + pub exec_output_tail: Option, +} + impl<'a> SandboxMetadataWriter<'a> { pub(crate) fn new( sandbox: &'a dyn Sandbox, @@ -173,7 +191,10 @@ impl<'a> SandboxMetadataWriter<'a> { self.sandbox .upload_file_from_local(local.path(), &remote) .await - .map_err(|err| SandboxMetadataError::Sandbox(err.display_with_causes()))?; + .map_err(|err| SandboxMetadataError::Operation { + message: err.display_with_causes(), + exec_output_tail: err.default_redacted_output_tail(), + })?; let stdout = exec_stdout( self.sandbox, @@ -186,12 +207,14 @@ impl<'a> SandboxMetadataWriter<'a> { .await?; let commit = parse_fast_import_mark(&stdout)?; let refspec = format!("{full_ref}:{full_ref}"); - let push_error = self - .sandbox - .git_push_ref(&refspec) - .await - .err() - .map(|err| err.to_string()); + let push_result = self.sandbox.git_push_ref(&refspec).await; + let push_error = match push_result { + Ok(()) => None, + Err(err) => Some(MetadataPushError { + message: err.display_with_causes(), + exec_output_tail: err.default_redacted_output_tail(), + }), + }; Ok(MetadataSnapshot { commit_sha: commit, push_error, @@ -262,13 +285,26 @@ fn parse_fast_import_mark(stdout: &str) -> Result .map(str::trim) .find(|line| !line.is_empty() && line.bytes().all(|byte| byte.is_ascii_hexdigit())) .map(ToString::to_string) - .ok_or_else(|| { - SandboxMetadataError::Git(format!( - "git fast-import did not report imported commit mark: {stdout:?}" - )) + .ok_or_else(|| SandboxMetadataError::Operation { + message: format!( + "git fast-import did not report imported commit mark (stdout_bytes={})", + stdout.len() + ), + exec_output_tail: stdout_output_tail(stdout), }) } +fn stdout_output_tail(stdout: &str) -> Option { + fabro_sandbox::ExecResult { + stdout: stdout.to_string(), + stderr: String::new(), + exit_code: Some(0), + termination: fabro_types::CommandTermination::Exited, + duration_ms: 0, + } + .default_redacted_output_tail() +} + fn fast_import_ident(author: &GitAuthor) -> String { let name = author .name @@ -357,11 +393,18 @@ async fn exec_stdout( let result = sandbox .exec_command(command, 30_000, None, env, None) .await - .map_err(|err| SandboxMetadataError::Sandbox(err.display_with_causes()))?; + .map_err(|err| SandboxMetadataError::Operation { + message: err.display_with_causes(), + exec_output_tail: err.default_redacted_output_tail(), + })?; if result.is_success() { Ok(result.stdout.trim().to_string()) } else { - Err(SandboxMetadataError::Git(exec_err(command, &result))) + let error = result.into_exec_error(command.to_string()); + Err(SandboxMetadataError::Operation { + message: error.display_with_causes(), + exec_output_tail: error.default_redacted_output_tail(), + }) } } @@ -373,25 +416,6 @@ async fn exec_ok( exec_stdout(sandbox, command, env).await.map(|_| ()) } -fn exec_err(label: &str, result: &fabro_sandbox::ExecResult) -> String { - if result.is_timed_out() { - return format!("{label} timed out after {}ms", result.duration_ms); - } - if result.is_cancelled() { - return format!("{label} cancelled after {}ms", result.duration_ms); - } - let detail = format!("{}{}", result.stdout, result.stderr); - let detail = detail.trim(); - if detail.is_empty() { - format!("{label} failed with exit {}", result.display_exit_code()) - } else { - format!( - "{label} failed with exit {}: {detail}", - result.display_exit_code() - ) - } -} - fn validate_metadata_path(path: &str) -> Result<(), SandboxMetadataError> { let invalid = path.is_empty() || path.starts_with('/') @@ -399,9 +423,167 @@ fn validate_metadata_path(path: &str) -> Result<(), SandboxMetadataError> { .split('/') .any(|segment| segment.is_empty() || segment == "." || segment == ".."); if invalid { - return Err(SandboxMetadataError::Git(format!( - "invalid metadata path: {path}" - ))); + return Err(SandboxMetadataError::Operation { + message: format!("invalid metadata path: {path}"), + exec_output_tail: None, + }); } Ok(()) } + +#[cfg(test)] +mod tests { + use async_trait::async_trait; + use fabro_sandbox::{DirEntry, ExecResult, GrepOptions, Sandbox}; + use fabro_types::CommandTermination; + use tokio_util::sync::CancellationToken; + + use super::*; + + struct ExecOnlySandbox { + result: ExecResult, + } + + #[async_trait] + impl Sandbox for ExecOnlySandbox { + async fn read_file( + &self, + _path: &str, + _offset: Option, + _limit: Option, + ) -> fabro_sandbox::Result { + unreachable!("read_file is not used by exec_stdout") + } + + async fn write_file(&self, _path: &str, _content: &str) -> fabro_sandbox::Result<()> { + unreachable!("write_file is not used by exec_stdout") + } + + async fn delete_file(&self, _path: &str) -> fabro_sandbox::Result<()> { + unreachable!("delete_file is not used by exec_stdout") + } + + async fn file_exists(&self, _path: &str) -> fabro_sandbox::Result { + unreachable!("file_exists is not used by exec_stdout") + } + + async fn list_directory( + &self, + _path: &str, + _depth: Option, + ) -> fabro_sandbox::Result> { + unreachable!("list_directory is not used by exec_stdout") + } + + async fn exec_command( + &self, + _command: &str, + _timeout_ms: u64, + _working_dir: Option<&str>, + _env_vars: Option<&HashMap>, + _cancel_token: Option, + ) -> fabro_sandbox::Result { + Ok(self.result.clone()) + } + + async fn grep( + &self, + _pattern: &str, + _path: &str, + _options: &GrepOptions, + ) -> fabro_sandbox::Result> { + unreachable!("grep is not used by exec_stdout") + } + + async fn glob( + &self, + _pattern: &str, + _path: Option<&str>, + ) -> fabro_sandbox::Result> { + unreachable!("glob is not used by exec_stdout") + } + + async fn download_file_to_local( + &self, + _remote_path: &str, + _local_path: &std::path::Path, + ) -> fabro_sandbox::Result<()> { + unreachable!("download_file_to_local is not used by exec_stdout") + } + + async fn upload_file_from_local( + &self, + _local_path: &std::path::Path, + _remote_path: &str, + ) -> fabro_sandbox::Result<()> { + unreachable!("upload_file_from_local is not used by exec_stdout") + } + + async fn initialize(&self) -> fabro_sandbox::Result<()> { + Ok(()) + } + + async fn cleanup(&self) -> fabro_sandbox::Result<()> { + Ok(()) + } + + fn working_directory(&self) -> &str { + "/work" + } + + fn platform(&self) -> &str { + "linux" + } + + fn os_version(&self) -> String { + "Linux".to_string() + } + } + + #[tokio::test] + async fn metadata_snapshot_exec_stdout_error_carries_projected_tail() { + let sandbox = ExecOnlySandbox { + result: ExecResult { + stdout: "push stdout".to_string(), + stderr: "remote: Permission denied".to_string(), + exit_code: Some(128), + termination: CommandTermination::Exited, + duration_ms: 7, + }, + }; + + let err = exec_stdout(&sandbox, "git push origin refs/heads/run", None) + .await + .unwrap_err(); + + assert!(err.to_string().contains("git push origin")); + assert_eq!( + err.exec_output_tail() + .as_ref() + .and_then(|tail| tail.stderr.as_deref()), + Some("remote: Permission denied") + ); + } + + #[test] + fn parse_fast_import_mark_error_is_log_safe_and_carries_projected_tail() { + let secret = "sk-ant-api03-xK9mZ2vL8nQ5rT1wY4bC7dF0gH3jE6pA"; + let stdout = format!("unexpected output {secret}\n\u{1b}[31mcolored\u{1b}[0m"); + + let err = parse_fast_import_mark(&stdout).unwrap_err(); + let message = err.to_string(); + + assert!(message.contains("stdout_bytes=")); + assert!(!message.contains("unexpected output")); + assert!(!message.contains(secret)); + + let stdout_tail = err + .exec_output_tail() + .and_then(|tail| tail.stdout) + .expect("stdout tail"); + assert!(stdout_tail.contains("REDACTED"), "{stdout_tail}"); + assert!(stdout_tail.contains("colored"), "{stdout_tail}"); + assert!(!stdout_tail.contains(secret), "{stdout_tail}"); + assert!(!stdout_tail.contains('\u{1b}'), "{stdout_tail}"); + } +}