diff --git a/docs/isolation-session/state-aware-rust.md b/docs/isolation-session/state-aware-rust.md index 960585a25..039903f62 100644 --- a/docs/isolation-session/state-aware-rust.md +++ b/docs/isolation-session/state-aware-rust.md @@ -190,10 +190,10 @@ wrong-nesting cases are rejected as `malformed_request`. **Config (none).** Exec uses only the cross-cutting `process` block on the top-level wire envelope (`commandLine`, `cwd`, `env`, `timeout`). -**Output.** Stdout is the agent process's live-streamed output (the SDK -discriminates this from a JSON envelope by exit code + stdout-parseability; -the dispatcher never emits a JSON envelope on stdout for exec on success). -The wxc-exec process exit code is the agent process's exit code. +**Output.** Stdout is the agent process's live-streamed output; the dispatcher +never emits a JSON envelope on stdout for a non-dry-run exec, so a failure's +`{error}` envelope goes to stderr instead. The wxc-exec process exit code is the +agent process's exit code. ### Stop diff --git a/docs/state-aware-lifecycle/mxc-state-aware-sandbox-api.md b/docs/state-aware-lifecycle/mxc-state-aware-sandbox-api.md index 961f481b7..a8359b4b6 100644 --- a/docs/state-aware-lifecycle/mxc-state-aware-sandbox-api.md +++ b/docs/state-aware-lifecycle/mxc-state-aware-sandbox-api.md @@ -765,15 +765,18 @@ the executor CLI represents the same outcomes through stdout, stderr, and its ex | Phase / outcome | stdout | stderr | |---|---|---| | Non-exec (provision, start, stop, deprovision), success or failure | Single JSON envelope (`{result}` or `{error}`) | Buffered MXC diagnostics and warnings, when produced; may be empty | +| Exec dry-run, success or failure | Single JSON envelope (`{result}` or `{error}`) | Buffered MXC diagnostics and warnings, when produced; may be empty | | Exec, dispatch succeeded | Script's stdout | Script's stderr plus buffered MXC diagnostics and warnings, when produced | -| Exec, dispatch failed | Single JSON envelope (`{error}`) | Buffered MXC diagnostics and warnings, when produced; may be empty | +| Exec, dispatch failed | Script's stdout, up to the point of failure | Single JSON envelope (`{error}`), after the script's stderr and any buffered MXC diagnostics | -`stdout` is authoritative: for non-exec phases it carries exactly one envelope; for exec -it carries either the script's output (success) or exactly one envelope (failure). -`stderr` is informational. MXC routes its diagnostic logger output to `stderr` in -state-aware mode so `stdout` remains parseable without sentinels. (One-shot dispatch -keeps its existing `stdout` logger behaviour — the stricter routing applies to -state-aware only.) +`stdout` is authoritative: for non-exec phases and exec dry-run it carries exactly one +envelope; for a non-dry-run exec it carries the script's output and nothing else. An exec +can fail after the script has already streamed output, so its error envelope goes to +`stderr` — appending it to `stdout` would leave neither the script's output nor the +envelope parseable. `stderr` is otherwise informational. MXC routes its diagnostic logger +output to `stderr` in state-aware mode so `stdout` remains parseable without sentinels. +(One-shot dispatch keeps its existing `stdout` logger behaviour — the stricter routing +applies to state-aware only.) When `--operation` is present, the executor selects the lifecycle contract before reading or decoding the configuration source. Every failure from that point onward — @@ -821,18 +824,22 @@ type NonExecResponseEnvelope = { result: TResult } | { error: ErrorEnve **Distinguishing exec dispatch-failure from script execution:** -The SDK uses exit code plus stdout content: - -- `exitCode == 0`: the script ran and exited successfully. SDK constructs - `{stdout, stderr, exitCode}` from PTY / pipe events. -- `exitCode != 0` AND stdout's entire content parses as a complete `{error: {...}}` - envelope: dispatch failed before the script ran; SDK surfaces the typed error. -- `exitCode != 0` AND stdout does NOT parse as an envelope: the script ran and exited +Which stream carries the typed error depends on whether the script could already +have written output, so the SDK discriminates differently per phase: + +- Non-exec phases and exec **dry-run**: stdout is exactly one envelope. `{error}` + is the typed failure; `{result}` is success. +- Non-dry-run **exec**, `exitCode == 0`: the script ran and exited successfully. + SDK constructs `{stdout, stderr, exitCode}` from PTY / pipe events. +- Non-dry-run **exec**, `exitCode != 0` AND the final non-empty line of stderr + parses as a complete `{error: {...}}` envelope: dispatch failed; SDK surfaces + the typed error. +- Non-dry-run **exec**, `exitCode != 0` otherwise: the script ran and exited non-zero. SDK constructs `{stdout, stderr, exitCode}`. -Because MXC diagnostic output is routed to `stderr` in state-aware mode, this -stdout-based discrimination has no false positives or negatives — the content is always -either pure envelope or pure script output. +For a non-dry-run exec, stdout is always pure script output, so it is never +parsed for an envelope. The executor writes its error envelope on its own line, +because a script's stderr may not end in a newline. `code` and `message` are always present. `code` is the machine-readable category a consumer branches on; `message` is the human-readable description, and for a failure diff --git a/docs/wsl/wslc-state-aware.md b/docs/wsl/wslc-state-aware.md index 9cab6ae94..237c4a68b 100644 --- a/docs/wsl/wslc-state-aware.md +++ b/docs/wsl/wslc-state-aware.md @@ -83,10 +83,12 @@ as `--sandbox-id`; the dispatcher derives the backend from the `wslc:` prefix (l For attached execution, a **successful** `exec` relays the script's raw stdout/stderr live from daemon frames and exits with the script's own exit code — it does **not** wrap the result in an envelope. Piped execution writes those same live frames into separate anonymous stdout/stderr -pipes returned to the in-process SDK caller; no stdin pipe is returned. Callers discriminate -attached dispatch failures via the exit code + whether stdout parses as an envelope. A timeout -on the attached relay surfaces as a backend error because that path cannot return a typed timeout; -the piped path reports it through its wait result. +pipes returned to the in-process SDK caller; no stdin pipe is returned. An attached dispatch +**failure** writes its `{error}` envelope to stderr, because the script's output may already own +stdout by the time the failure is known — so stdout carries the script's output either way, and a +caller reads the typed error from stderr. A timeout on the attached relay surfaces as a backend +error because that path cannot return a typed timeout; the piped path reports it through its wait +result. ### exec admission, cancellation, and failure containment @@ -105,8 +107,14 @@ without creating the process. Live output uses bounded queues in both the daemon and the in-process native pipe bridge. If a caller does not drain stdout/stderr quickly enough, excess -output is dropped and completion becomes an explicit backend error reporting -truncation; incomplete output is never reported as successful. +output is dropped and the run is reported as truncated; incomplete output is +never reported as successful. A run that would otherwise have exited cleanly +becomes an explicit backend error carrying the process's exit code in +`details.exitCode`. A run that timed out or was cancelled keeps that outcome — +truncation is reported alongside it rather than replacing it. For an in-process +piped caller that pairing is only available on a clean exit: `ExecOutcome` has no +field for a modifier, so a piped run that both timed out and truncated reports +only the timeout. If process termination cannot be positively confirmed after creation, the container is quarantined and cannot be started or used for another exec. The diff --git a/src/backends/wslc/common/src/daemon_client.rs b/src/backends/wslc/common/src/daemon_client.rs index 89267e87e..afc94d9ea 100644 --- a/src/backends/wslc/common/src/daemon_client.rs +++ b/src/backends/wslc/common/src/daemon_client.rs @@ -138,6 +138,14 @@ pub struct ExecResult { /// Terminal outcome of a streaming daemon exec. pub type DaemonExecOutcome = ExecTerminal; +/// How a streaming exec finished, and whether the daemon had to drop live +/// output on the way there. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct DaemonExecCompletion { + pub outcome: DaemonExecOutcome, + pub truncated: bool, +} + /// An exec request that the daemon has admitted and whose pipe is now carrying /// only the [`StreamFrame`] data phase. #[derive(Debug)] @@ -150,27 +158,53 @@ impl AdmittedExec { pub(crate) fn read_to_completion( mut self, mut on_output: impl FnMut(OutStream, &[u8]), - ) -> DaemonResult { + ) -> DaemonResult { + let mut truncated = false; loop { - match read_frame::(&mut self.pipe)? { - StreamFrame::Stdout { data } => on_output(OutStream::Stdout, &data), - StreamFrame::Stderr { data } => on_output(OutStream::Stderr, &data), - StreamFrame::Exit { code } => return Ok(DaemonExecOutcome::Exited(code)), - StreamFrame::TimedOut => return Ok(DaemonExecOutcome::TimedOut), - StreamFrame::Cancelled => return Ok(DaemonExecOutcome::Cancelled), + let outcome = match read_frame::(&mut self.pipe)? { + StreamFrame::Stdout { data } => { + on_output(OutStream::Stdout, &data); + continue; + } + StreamFrame::Stderr { data } => { + on_output(OutStream::Stderr, &data); + continue; + } + StreamFrame::Truncated => { + truncated = true; + continue; + } + StreamFrame::Exit { code } => DaemonExecOutcome::Exited(code), + StreamFrame::TimedOut => DaemonExecOutcome::TimedOut, + StreamFrame::Cancelled => DaemonExecOutcome::Cancelled, StreamFrame::Error { message } => { - return Err(DaemonError::transport(format!("exec failed: {message}"))) + return Err(DaemonError::transport(format!( + "exec failed: {message}{}", + truncation_suffix(truncated) + ))) } StreamFrame::Stdin { .. } => { return Err(DaemonError::transport( "protocol error: daemon sent a Stdin frame to the client", )) } - } + }; + return Ok(DaemonExecCompletion { outcome, truncated }); } } } +/// Suffix naming lost output, for an error whose own classification the caller +/// still needs. +pub(crate) fn truncation_suffix(truncated: bool) -> &'static str { + if truncated { + " (live output was truncated: it was not drained fast enough and a bounded output queue \ + overflowed)" + } else { + "" + } +} + /// A typed failure from a daemon call. `Daemon` carries the daemon's stable /// [`ErrKind`] token so the state-aware backend can map it onto the matching /// `MxcError` code (e.g. `NotProvisioned` / `NotStarted`) without string @@ -339,17 +373,31 @@ impl DaemonClient { pub fn exec(&self, config: ExecConfig) -> DaemonResult { let mut stdout = Vec::new(); let mut stderr = Vec::new(); - let outcome = self.exec_streaming(config, |stream, data| match stream { + let completion = self.exec_streaming(config, |stream, data| match stream { OutStream::Stdout => stdout.extend_from_slice(data), OutStream::Stderr => stderr.extend_from_slice(data), })?; - let exit_code = match outcome { + let exit_code = match completion.outcome { DaemonExecOutcome::Exited(code) => code, - DaemonExecOutcome::TimedOut => return Err(DaemonError::transport("exec timed out")), + DaemonExecOutcome::TimedOut => { + return Err(DaemonError::transport(format!( + "exec timed out{}", + truncation_suffix(completion.truncated) + ))) + } DaemonExecOutcome::Cancelled => { - return Err(DaemonError::transport("exec was cancelled")) + return Err(DaemonError::transport(format!( + "exec was cancelled{}", + truncation_suffix(completion.truncated) + ))) } }; + if completion.truncated { + return Err(DaemonError::transport(format!( + "exec output was truncated before it could be captured (the process exited \ + {exit_code})" + ))); + } Ok(ExecResult { exit_code, stdout, @@ -369,7 +417,7 @@ impl DaemonClient { &self, config: ExecConfig, on_output: impl FnMut(OutStream, &[u8]), - ) -> DaemonResult { + ) -> DaemonResult { self.admit_exec(config)?.read_to_completion(on_output) } diff --git a/src/backends/wslc/common/src/daemon_protocol.rs b/src/backends/wslc/common/src/daemon_protocol.rs index fbe4aa6a2..d74dbd49a 100644 --- a/src/backends/wslc/common/src/daemon_protocol.rs +++ b/src/backends/wslc/common/src/daemon_protocol.rs @@ -50,7 +50,7 @@ pub const MAX_EXEC_ID_BYTES: usize = 128; /// A new optional field counts: these structs do not deny unknown fields, so a /// daemon predating one drops it and acts on a request it only partly /// understood. -pub const PROTOCOL_VERSION: u32 = 5; +pub const PROTOCOL_VERSION: u32 = 6; fn deserialize_exec_id<'de, D>(deserializer: D) -> Result where @@ -310,6 +310,8 @@ pub enum StreamFrame { /// Daemon→client: terminal frame; an explicit cancellation request was /// accepted and the process was confirmed terminated. Cancelled, + /// Daemon→client: live output was dropped; the terminal frame still follows. + Truncated, /// Daemon→client: terminal frame; the exec failed before or during the run. Error { message: String }, } @@ -555,6 +557,7 @@ mod tests { roundtrip(StreamFrame::Exit { code: 42 }); roundtrip(StreamFrame::TimedOut); roundtrip(StreamFrame::Cancelled); + roundtrip(StreamFrame::Truncated); roundtrip(StreamFrame::Error { message: "spawn failed".to_string(), }); diff --git a/src/backends/wslc/common/src/state_aware.rs b/src/backends/wslc/common/src/state_aware.rs index 6d9fbdd29..f400d7b4a 100644 --- a/src/backends/wslc/common/src/state_aware.rs +++ b/src/backends/wslc/common/src/state_aware.rs @@ -33,7 +33,7 @@ use wxc_common::state_aware_backend::{ use wxc_common::validator::validate_state_aware_network_policy_support; use crate::container_steps::OutStream; -use crate::daemon_client::{DaemonClient, DaemonError, DaemonExecOutcome}; +use crate::daemon_client::{truncation_suffix, DaemonClient, DaemonError, DaemonExecOutcome}; use crate::daemon_protocol::{ DeprovisionConfig, ErrKind, ExecConfig, NetworkMode, ProvisionConfig, StartConfig, StopConfig, VolumeMount, @@ -251,7 +251,7 @@ fn exec_relayed(client: DaemonClient, config: ExecConfig) -> Result Result { + return Err(truncated_run_error(code)) + } DaemonExecOutcome::Exited(code) => code, DaemonExecOutcome::TimedOut => { return Err(MxcError::backend_error(format!( - "WSLc exec timed out after {timeout_ms}ms" + "WSLc exec timed out after {timeout_ms}ms{}", + truncation_suffix(completion.truncated) ))) } DaemonExecOutcome::Cancelled => { - return Err(MxcError::backend_error( - "WSLc relayed exec was cancelled unexpectedly", - )) + return Err(MxcError::backend_error(format!( + "WSLc relayed exec was cancelled unexpectedly{}", + truncation_suffix(completion.truncated) + ))) } }; @@ -349,25 +354,24 @@ fn exec_piped( OutStream::Stderr => stderr_writer.write(bytes), }) }) - .map(|outcome| match outcome { - DaemonExecOutcome::Exited(code) => ExecOutcome::Exited(code), - DaemonExecOutcome::TimedOut => ExecOutcome::TimedOut, - // `SandboxProcess::kill` is a request followed by reaping; - // there is no distinct cancelled variant in `ExecOutcome`. - DaemonExecOutcome::Cancelled => ExecOutcome::Exited(-1), - }) - .map_err(map_daemon_error); - let result = match result { - Ok(ExecOutcome::Exited(_)) - if stdout_overflow.has_overflowed() || stderr_overflow.has_overflowed() => - { - Err(MxcError::backend_error( - "WSLc live output was truncated because the caller did not drain the \ - synthesized stdout/stderr pipes fast enough", - )) - } - other => other, - }; + .map_err(map_daemon_error) + .and_then(|completion| { + // Either end of the bridge can drop output: the daemon's + // queue on the way out, or these pipes if the caller is slow. + let truncated = completion.truncated + || stdout_overflow.has_overflowed() + || stderr_overflow.has_overflowed(); + match completion.outcome { + DaemonExecOutcome::Exited(code) if truncated => { + Err(truncated_run_error(code)) + } + DaemonExecOutcome::Exited(code) => Ok(ExecOutcome::Exited(code)), + DaemonExecOutcome::TimedOut => Ok(ExecOutcome::TimedOut), + // `SandboxProcess::kill` is a request followed by reaping; + // there is no distinct cancelled variant in `ExecOutcome`. + DaemonExecOutcome::Cancelled => Ok(ExecOutcome::Exited(-1)), + } + }); stdout_writer.close(); stderr_writer.close(); let _ = done_tx.send(result); @@ -458,6 +462,18 @@ fn connect_daemon() -> Result { }) } +/// The process finished, but the caller's copy of its output is incomplete. +/// +/// Reported as a failure so a short capture is never mistaken for a whole one, +/// with `details.exitCode` keeping the code the process produced. +fn truncated_run_error(exit_code: i32) -> MxcError { + MxcError::backend_error( + "WSLc live output was truncated: it was not drained fast enough and a bounded output \ + queue overflowed", + ) + .with_details(serde_json::json!({ "exitCode": exit_code })) +} + /// Map a typed [`DaemonError`] onto the matching wire-format [`MxcError`] code. fn map_daemon_error(err: DaemonError) -> MxcError { match err { @@ -611,6 +627,27 @@ mod tests { NetworkIngressPolicy, ProxyAddress, ProxyConfig, }; + /// The exit code is unrecoverable once dropped, so failing the call must not + /// discard it. + #[test] + fn a_truncated_run_reports_the_exit_code_it_produced() { + let error = truncated_run_error(3); + assert_eq!( + error.code, + wxc_common::mxc_error::MxcErrorCode::BackendError + ); + assert_eq!( + error.details.as_ref().and_then(|d| d.get("exitCode")), + Some(&serde_json::json!(3)) + ); + } + + #[test] + fn an_untruncated_run_adds_no_suffix() { + assert_eq!(truncation_suffix(false), ""); + assert!(truncation_suffix(true).contains("truncated")); + } + #[test] fn backend_key_matches_wire_format() { assert_eq!( diff --git a/src/backends/wslc/daemon/src/control_server.rs b/src/backends/wslc/daemon/src/control_server.rs index 505fafa65..6d7555aed 100644 --- a/src/backends/wslc/daemon/src/control_server.rs +++ b/src/backends/wslc/daemon/src/control_server.rs @@ -509,7 +509,7 @@ async fn write_exec_result( // output; the sink's sender also drops as the run returns, so `output` may // instead close first — the `None` arm handles that and awaits the exit code. let mut done = done; - let terminal = loop { + let (notice, terminal) = loop { tokio::select! { biased; result = &mut done => { @@ -517,7 +517,7 @@ async fn write_exec_result( while let Ok(chunk) = output.try_recv() { write_frame(pipe, &output_frame(chunk)).await?; } - break terminal_frame(result, &overflowed); + break terminal_frames(result, &overflowed); } chunk = output.recv() => match chunk { Some(chunk) => { @@ -525,10 +525,13 @@ async fn write_exec_result( } // Senders dropped before `done` fired (normal path): the run has // completed and every chunk is flushed. Await the exit code. - None => break terminal_frame(done.await, &overflowed), + None => break terminal_frames(done.await, &overflowed), }, } }; + if let Some(notice) = notice { + write_frame(pipe, ¬ice).await?; + } write_frame(pipe, &terminal).await?; Ok(()) } @@ -541,24 +544,21 @@ fn output_frame((kind, data): (OutStream, Vec)) -> StreamFrame { } } -/// Choose the exec's terminal [`StreamFrame`]. A latched `overflowed` means the -/// sink had to drop live output because the client did not drain the daemon's -/// bounded queue fast enough, so a would-be clean [`StreamFrame::Exit`] is -/// reported as a truncation [`StreamFrame::Error`] instead — the client must not -/// treat a short stream as a successful, complete run. A genuine run failure -/// (already an `Error`) is strictly more informative and passes through -/// unchanged. -fn terminal_frame( +/// Choose the exec's terminal [`StreamFrame`], and the notice that precedes it +/// when the sink had to drop live output. +/// +/// Truncation travels ahead of the terminal rather than replacing it: every +/// terminal carries something the client cannot reconstruct — an exit code, or +/// why the run ended. +fn terminal_frames( result: Result, oneshot::error::RecvError>, overflowed: &AtomicBool, -) -> StreamFrame { - match exit_terminal(result) { - StreamFrame::Exit { .. } if overflowed.load(Ordering::Relaxed) => StreamFrame::Error { - message: "WSLc: live output was truncated — the client did not read the exec stream \ - fast enough and the daemon's bounded output queue overflowed" - .to_string(), - }, - other => other, +) -> (Option, StreamFrame) { + let terminal = exit_terminal(result); + if overflowed.load(Ordering::Relaxed) { + (Some(StreamFrame::Truncated), terminal) + } else { + (None, terminal) } } @@ -1079,12 +1079,10 @@ mod tests { assert!(saw_exit, "the stream must end with an Exit terminal"); } - /// Overflow regression: when the sink latched `overflowed` (it dropped live - /// output because the client did not drain fast enough), the terminal frame - /// must be a truncation `Error` — never a clean `Exit` the client would - /// mistake for a complete run. + /// Overflow regression: the client must be told, and must still receive the + /// exit code the process produced. #[tokio::test] - async fn overflow_yields_truncation_error_terminal() { + async fn overflow_precedes_a_clean_exit_without_replacing_it() { let (mut server, mut client) = duplex(64 * 1024); let (done_tx, done_rx) = oneshot::channel::>(); let (out_tx, output) = mpsc::channel(16); @@ -1120,12 +1118,85 @@ mod tests { } ); let terminal: StreamFrame = read_frame(&mut client).await.unwrap(); - match terminal { - StreamFrame::Error { message } => { - assert!(message.contains("truncated"), "message was {message:?}"); - } - other => panic!("expected a truncation Error terminal, got {other:?}"), - } + assert_eq!(terminal, StreamFrame::Truncated); + assert_eq!( + read_frame::<_, StreamFrame>(&mut client).await.unwrap(), + StreamFrame::Exit { code: 0 } + ); + assert!(read_frame::<_, StreamFrame>(&mut client).await.is_err()); + } + + #[tokio::test] + async fn overflow_precedes_a_timeout_terminal_without_replacing_it() { + assert_eq!( + overflowed_frames(ExecTerminal::TimedOut).await, + (Some(StreamFrame::Truncated), StreamFrame::TimedOut) + ); + } + + #[tokio::test] + async fn overflow_precedes_a_cancellation_terminal_without_replacing_it() { + assert_eq!( + overflowed_frames(ExecTerminal::Cancelled).await, + (Some(StreamFrame::Truncated), StreamFrame::Cancelled) + ); + } + + #[tokio::test] + async fn a_clean_run_emits_no_truncation_notice() { + let (mut server, mut client) = duplex(64 * 1024); + let (done_tx, done_rx) = oneshot::channel::>(); + let (out_tx, output) = mpsc::channel(16); + done_tx.send(Ok(ExecTerminal::TimedOut)).unwrap(); + drop(out_tx); + + write_exec_result( + &mut server, + Ok(ExecStream { + done: done_rx, + output, + overflowed: Arc::new(AtomicBool::new(false)), + registration: test_registration(), + }), + ) + .await + .unwrap(); + drop(server); + + let admit: DaemonResponse = read_frame(&mut client).await.unwrap(); + assert_eq!(admit, DaemonResponse::Ok); + assert_eq!( + read_frame::<_, StreamFrame>(&mut client).await.unwrap(), + StreamFrame::TimedOut + ); + assert!(read_frame::<_, StreamFrame>(&mut client).await.is_err()); + } + + async fn overflowed_frames(terminal: ExecTerminal) -> (Option, StreamFrame) { + let (mut server, mut client) = duplex(64 * 1024); + let (done_tx, done_rx) = oneshot::channel::>(); + let (out_tx, output) = mpsc::channel(16); + done_tx.send(Ok(terminal)).unwrap(); + drop(out_tx); + + write_exec_result( + &mut server, + Ok(ExecStream { + done: done_rx, + output, + overflowed: Arc::new(AtomicBool::new(true)), + registration: test_registration(), + }), + ) + .await + .unwrap(); + drop(server); + + let admit: DaemonResponse = read_frame(&mut client).await.unwrap(); + assert_eq!(admit, DaemonResponse::Ok); + let first: StreamFrame = read_frame(&mut client).await.unwrap(); + let second: StreamFrame = read_frame(&mut client).await.unwrap(); assert!(read_frame::<_, StreamFrame>(&mut client).await.is_err()); + (Some(first), second) } } diff --git a/src/core/wxc/src/main.rs b/src/core/wxc/src/main.rs index 734253d4c..34d52a159 100644 --- a/src/core/wxc/src/main.rs +++ b/src/core/wxc/src/main.rs @@ -507,9 +507,10 @@ fn sandbox_id_for_identity_record( /// Drives the state-aware dispatch flow. On envelope success, writes the /// JSON to stdout and exits 0. On exec success, exits with the script's /// exit code (output already streamed). On failure, writes a JSON error -/// envelope to stdout and exits 1. Diagnostic logger output goes to stderr -/// regardless of mode (per design §7.3 stream protocol — stdout reserved -/// for the response envelope). +/// envelope and exits 1 — to stderr for a live exec, whose stdout belongs +/// to the script, and to stdout otherwise. Diagnostic logger output goes to +/// stderr regardless of mode (per design §7.3 stream protocol — stdout +/// reserved for the response envelope). fn run_state_aware_main( parsed: ParsedStateAwareRequest, dry_run: bool, @@ -673,10 +674,9 @@ fn run_state_aware_main( elapsed, ); - // On dispatch failure, route the error to the auxiliary diagnostic sinks - // only (log file / diagnostic pipe) — never the primary buffer/stderr — so - // the stdout error envelope written below stays the single client-facing - // channel and is not shadowed by a duplicate on stderr. + // Route dispatch failures to the auxiliary diagnostic sinks only (log file + // / diagnostic pipe), so the envelope written below is the single + // client-facing copy of the error. if let Err(error) = &outcome { log_state_aware_dispatch_error(logger, error); } @@ -689,7 +689,7 @@ fn run_state_aware_main( if !buffered.is_empty() { eprint!("{}", buffered); } - match finalize_state_aware_outcome(outcome) { + match finalize_state_aware_outcome(outcome, phase, dry_run) { StateAwareExit::Envelope(json) => { println!("{}", json); process::exit(0); @@ -699,6 +699,12 @@ fn run_state_aware_main( println!("{}", json); process::exit(1); } + StateAwareExit::ExecError(json) => { + // The script's own stderr may not end in a newline, and gluing the + // envelope onto those bytes would leave it unparseable. + eprintln!("\n{}", json); + process::exit(1); + } } } @@ -713,16 +719,33 @@ enum StateAwareExit { ExecCode(i32), /// Print this JSON error envelope to stdout, then exit 1. Error(String), + /// Print this JSON error envelope to stderr, then exit 1. + ExecError(String), } /// Map a dispatch outcome to its terminal exit action. Pure — it neither prints /// nor exits — so [`run_state_aware_main`]'s final branch can be exercised in a -/// unit test. The `-> !` caller performs the actual stdout write + exit. -fn finalize_state_aware_outcome(outcome: Result) -> StateAwareExit { +/// unit test. The `-> !` caller performs the actual write + exit. +fn finalize_state_aware_outcome( + outcome: Result, + phase: &str, + dry_run: bool, +) -> StateAwareExit { match outcome { Ok(DispatchOutcome::Envelope(value)) => StateAwareExit::Envelope(value.to_string()), Ok(DispatchOutcome::ExecCompleted { exit_code }) => StateAwareExit::ExecCode(exit_code), - Err(e) => StateAwareExit::Error(error_envelope_string(&e)), + Err(e) => { + let json = error_envelope_string(&e); + + // A failed exec has already streamed the script's output to stdout, + // so an envelope appended there would corrupt both. A dry run + // streams nothing and keeps its envelope on stdout. + if phase == "exec" && !dry_run { + StateAwareExit::ExecError(json) + } else { + StateAwareExit::Error(json) + } + } } } @@ -3155,7 +3178,7 @@ mod tests { fn finalize_maps_envelope_to_stdout_exit_zero() { let outcome: Result = Ok(DispatchOutcome::Envelope(serde_json::json!({ "ok": true }))); - match finalize_state_aware_outcome(outcome) { + match finalize_state_aware_outcome(outcome, "provision", false) { StateAwareExit::Envelope(json) => { assert_eq!(json, r#"{"ok":true}"#); } @@ -3168,7 +3191,7 @@ mod tests { let outcome: Result = Ok(DispatchOutcome::ExecCompleted { exit_code: 7 }); assert!(matches!( - finalize_state_aware_outcome(outcome), + finalize_state_aware_outcome(outcome, "exec", false), StateAwareExit::ExecCode(7) )); } @@ -3177,7 +3200,7 @@ mod tests { fn finalize_maps_error_to_serialised_envelope() { let outcome: Result = Err(MxcError::malformed_request("boom".to_string())); - match finalize_state_aware_outcome(outcome) { + match finalize_state_aware_outcome(outcome, "provision", false) { StateAwareExit::Error(json) => { // Must be a parseable envelope carrying the error code so consumers // that key off `error.code` still work. @@ -3187,4 +3210,28 @@ mod tests { other => panic!("expected Error, got {other:?}"), } } + + #[test] + fn finalize_routes_a_failed_exec_to_stderr() { + let outcome: Result = + Err(MxcError::backend_error("output was truncated".to_string())); + match finalize_state_aware_outcome(outcome, "exec", false) { + StateAwareExit::ExecError(json) => { + // Still a parseable envelope; only the stream it lands on changes. + let parsed: serde_json::Value = serde_json::from_str(&json).unwrap(); + assert!(parsed["error"]["code"].is_string(), "{json}"); + } + other => panic!("expected ExecError, got {other:?}"), + } + } + + #[test] + fn finalize_keeps_a_failed_exec_dry_run_on_stdout() { + let outcome: Result = + Err(MxcError::malformed_request("boom".to_string())); + assert!(matches!( + finalize_state_aware_outcome(outcome, "exec", true), + StateAwareExit::Error(_) + )); + } } diff --git a/tests/scripts/run_isolation_session_state_aware_tests.ps1 b/tests/scripts/run_isolation_session_state_aware_tests.ps1 index b48b3165b..20ffd6a15 100644 --- a/tests/scripts/run_isolation_session_state_aware_tests.ps1 +++ b/tests/scripts/run_isolation_session_state_aware_tests.ps1 @@ -311,6 +311,14 @@ function Parse-Envelope { try { $Stdout | ConvertFrom-Json } catch { $null } } +# The executor writes the exec error envelope after any warnings and the +# diagnostic buffer, so it is the last non-empty line on stderr. +function Parse-StderrEnvelope { + param([string]$Stderr) + $last = ($Stderr -split '\r?\n' | Where-Object { $_.Trim() } | Select-Object -Last 1) + Parse-Envelope -Stdout $last +} + # Decodes the `iso:` sandbox id payload. Returns $null # if the id is not in that shape. base64url differs from standard base64 in two # ways that both have to be undone before [Convert] will accept it: the '-' and @@ -927,7 +935,7 @@ try { } $r = Invoke-StateAware -Request $req Assert-True ($r.ExitCode -ne 0) "exit code is non-zero (policy rejected)" - $envObj = Parse-Envelope -Stdout $r.Stdout + $envObj = Parse-StderrEnvelope -Stderr $r.Stderr $code = if ($envObj) { $envObj.error.code } else { '' } Assert-True ($code -eq 'policy_validation') "error.code is 'policy_validation' (got '$code')" $msg = if ($envObj) { [string]$envObj.error.message } else { '' } diff --git a/tests/scripts/run_wslc_state_aware_tests.ps1 b/tests/scripts/run_wslc_state_aware_tests.ps1 index 83f4fafe9..91fce01d4 100644 --- a/tests/scripts/run_wslc_state_aware_tests.ps1 +++ b/tests/scripts/run_wslc_state_aware_tests.ps1 @@ -344,6 +344,14 @@ function Parse-Envelope { try { $Stdout | ConvertFrom-Json } catch { $null } } +# The executor writes the exec error envelope after any warnings and the +# diagnostic buffer, so it is the last non-empty line on stderr. +function Parse-StderrEnvelope { + param([string]$Stderr) + $last = ($Stderr -split '\r?\n' | Where-Object { $_.Trim() } | Select-Object -Last 1) + Parse-Envelope -Stdout $last +} + # Which arm of the envelope is present. function Envelope-Arm { param($Envelope) @@ -1082,7 +1090,7 @@ try { $req = @{ phase = 'exec'; sandboxId = $script:edgeSandboxId; process = @{ commandLine = 'echo should-not-run'; timeout = 30000 } } $r = Invoke-StateAware -Request $req Assert-True ($r.ExitCode -ne 0) "exit code is non-zero (exec before start rejected)" - $envObj = Parse-Envelope -Stdout $r.Stdout + $envObj = Parse-StderrEnvelope -Stderr $r.Stderr $code = if ($envObj) { $envObj.error.code } else { '' } Assert-True ($code -eq 'not_started') "error.code is 'not_started' (got '$code')" } | Out-Null @@ -1104,7 +1112,7 @@ try { $slow = @{ phase = 'exec'; sandboxId = $script:edgeSandboxId; process = @{ commandLine = 'sleep 30'; timeout = 3000 } } $r = Invoke-StateAware -Request $slow Assert-True ($r.ExitCode -ne 0) "timed-out exec exits non-zero" - $envObj = Parse-Envelope -Stdout $r.Stdout + $envObj = Parse-StderrEnvelope -Stderr $r.Stderr $code = if ($envObj) { $envObj.error.code } else { '' } Assert-True ($code -eq 'backend_error') "timeout maps to 'backend_error' (got '$code')" @@ -1115,6 +1123,38 @@ try { } | Out-Null } + # F2b: the command emits output before its timeout fires, which is the case + # where an envelope on stdout would corrupt the script's output. + if ($edgeStartedOk) { + Run-StateAwareTest "F: post-admission exec failure keeps stdout clean" { + $req = @{ phase = 'exec'; sandboxId = $script:edgeSandboxId; process = @{ commandLine = "sh -c 'echo PRE_FAILURE_MARKER; sleep 30'"; timeout = 5000 } } + $r = Invoke-StateAware -Request $req + Assert-True ($r.ExitCode -ne 0) "post-admission failure exits non-zero" + Assert-True ($r.Stdout -match 'PRE_FAILURE_MARKER') ` + "stdout carries the script's output ($($r.Stdout.Trim()))" + Assert-True ($r.Stdout -notmatch '"error"') ` + "stdout carries no envelope fragment ($($r.Stdout.Trim()))" + $envObj = Parse-StderrEnvelope -Stderr $r.Stderr + $code = if ($envObj) { $envObj.error.code } else { '' } + Assert-True ($code -eq 'backend_error') "error.code is 'backend_error' on stderr (got '$code')" + } | Out-Null + } + + # F2c: printf, not echo, so the script's stderr ends without a newline. + if ($edgeStartedOk) { + Run-StateAwareTest "F: exec error envelope survives unterminated script stderr" { + $req = @{ phase = 'exec'; sandboxId = $script:edgeSandboxId; process = @{ commandLine = "sh -c 'printf SCRIPT_STDERR_NO_NEWLINE >&2; sleep 30'"; timeout = 5000 } } + $r = Invoke-StateAware -Request $req + Assert-True ($r.ExitCode -ne 0) "post-admission failure exits non-zero" + Assert-True ($r.Stderr -match 'SCRIPT_STDERR_NO_NEWLINE') ` + "stderr carries the script's unterminated output" + $envObj = Parse-StderrEnvelope -Stderr $r.Stderr + $code = if ($envObj) { $envObj.error.code } else { '' } + Assert-True ($code -eq 'backend_error') ` + "the envelope is still parseable on its own line (got '$code')" + } | Out-Null + } + # F3: working directory (cwd) is honored per exec. if ($edgeStartedOk) { Run-StateAwareTest "F: exec honors working directory (cwd)" {