diff --git a/CHANGELOG.md b/CHANGELOG.md index 1134fdea..0680a721 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -32,6 +32,57 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 reach a terminal either way, so a person watching a build sees exactly what they saw before. +- **A command's stderr now comes back as the command wrote it.** `dl -- ` + reaches the container through `devpod ssh --command`, which asks for no pty, and + without a pty the container's stderr is folded into devpod's own -- through + devpod's stream logger, which reformats every line it carries. Measured against + devpod 0.26.1, `dl ws -- sh -c 'echo ERR >&2'` gave back a timestamp, a coloured + `info` tag, the text, and `stream_logger.go:492`. stdout was already clean and + had been for as long as anyone had looked, so a caller could parse a command's + JSON and not its compiler's diagnostics, and `docs/agents-using-dl.md` carried a + whole section saying so beside a `2>&1` workaround. That section is gone; stderr + is the fifth clause of the published contract now, and + `test_stderr_is_the_commands_output_verbatim` has stopped being a strict xfail. + + The fix is devpod's own `--log-output json`, on the `devpod ssh` invocation and + nowhere else. Its neighbour `raw` is the obvious choice and is a trap worth + naming, because taking it would have broken the *first* clause of the same + contract while fixing the last. devpod means to pass a remote exit status + through and cannot: its top-level handler type-asserts on `*ssh.ExitError` after + wrapping it three times with `%w`, so every nonzero remote exit lands on the + generic failure path and exits 1 with the real status buried in a `fatal` line. + dl recovers the number by reading that line, and it anchors on the word `fatal` + to be sure the sentence is devpod's report and not a remote program printing the + same words. Under `raw` the report is `tunnel to container: run in container: + ssh session: Process exited with status 42` with no tag at all, the recovery + returns nothing, and `dl ws -- 'exit 42'` quietly stops exiting 42. `--silent` + fails the other way and swallows the command's stderr outright. + + json keeps the level as a field. So the fatal is now read off `"level":"fatal"` + rather than off a coloured tag in the text, which is both a stronger anchor and + one a remote program cannot forge: devpod wraps whatever the container writes in + a record of its own at `info`, escaping it, so a container printing an entire + fatal record verbatim arrives as that record's `message` and is forwarded as the + text it is. Everything else is forwarded as the bare `message`, which for the + command's stderr is the command's bytes. A line that is not a record at all -- + an older devpod, the plain log of the attach route, anything on the stream that + is not a log line -- falls through to the predicates that were already there, so + nothing about a devpod that does not know the flag changes. + + Deliberately not passed on a bare `dl ` attach. That route gets a pty, and + under one the container's stderr never touches this stream: the only thing json + would change is the look of devpod's own warnings to the person sitting in front + of them, trading a coloured `warn` tag for nothing. So an interactive session + logs exactly as it did, and the flag goes only where there is something to + unwrap. + + Two things the clause does not promise, both now written on the page. Lines are + still read one at a time, so a command's unterminated last line arrives with a + newline it did not write; and devpod's logger strips ANSI escapes from what it + carries, so a tool that colours its errors arrives uncoloured -- which, since + the command is looking at a pipe rather than a terminal, most tools would have + done for themselves. + ## [0.48.0] - 2026-09-13 ### Fixed diff --git a/docs/agents-using-dl.md b/docs/agents-using-dl.md index c29b8102..288bfc16 100644 --- a/docs/agents-using-dl.md +++ b/docs/agents-using-dl.md @@ -13,7 +13,7 @@ that matter most to a caller are exactly the parts a refactor cannot see it is b ## The subprocess contract -`dl -- ` is an ordinary subprocess, and four things about it are +`dl -- ` is an ordinary subprocess, and five things about it are promised rather than incidental. **The exit status is the command's.** `dl ws -- sh -c 'exit 42'` exits 42. `dl`'s own @@ -54,6 +54,31 @@ all, so the guard and the page agreed with each other and not with the binary. A that parsed `dl ws -- cat some.json` worked until the first time somebody stopped the workspace. +**stderr is the command's too.** `dl ws -- sh -c 'echo boom >&2'` puts `boom` on stderr +and nothing else around it, so a compiler's diagnostics and a test runner's traceback +arrive parseable. `dl`'s own narration shares that stream, and it all comes before the +command starts, so the command's output is the tail of it. + +Two caveats worth knowing before you match on it. The command's stderr is still read a +line at a time on the way out, so a partial last line arrives with a newline appended +that the command did not write. And devpod's transport strips ANSI escapes from it, so +a tool that colours its errors arrives uncoloured; since the command sees a pipe rather +than a terminal, most tools emit no colour there anyway. + +This clause used to be the one the transport did not keep, and callers were told to +merge the streams inside the container instead. That merge still works and is still the +right call when you want one interleaved stream rather than two: + +```bash +dl ws -- sh -c 'make test 2>&1' +``` + +Note where the redirection is. Inside the command `dl` is asked to run, both streams +arrive on stdout in the order the command wrote them. `dl ws -- make test 2>&1` merges +on the host instead, and folds `dl`'s own narration in with the output. It is no longer +a workaround for anything, though, so reach for it only when you actually want the +interleaving. + **stdin is the command's.** `echo input | dl ws -- cat` reaches the command inside the container. @@ -66,38 +91,10 @@ folder is the devcontainer's own choice and not something `dl` imposes, so read rather than assuming a path: `pwd` in the container is the honest answer, and it is `/workspaces/` only for devcontainers that do not say otherwise. -These four are pinned by `test/e2e/test_agent_subprocess_contract.py`, which builds one +These five are pinned by `test/e2e/test_agent_subprocess_contract.py`, which builds one real workspace and asks each of them of it. They are e2e and skipped by default, because they need a Docker daemon. -## stderr is not yours yet - -The one place the contract does not hold. A command's stderr comes back through devpod's -stream logger rather than as itself: - -``` -$ dl ws -- sh -c 'echo boom >&2' -11:18:55 info boom stream_logger.go:492 -``` - -Timestamped, level-prefixed, ANSI-coloured and with a Go source location appended. For a -caller that is reading a compiler's diagnostics or a test runner's traceback off stderr, -this is the difference between output it can parse and output it cannot. - -Until that is fixed, merge the streams inside the container rather than outside it: - -```bash -dl ws -- sh -c 'make test 2>&1' -``` - -The merge happens before devpod sees the output, so both streams arrive on stdout -verbatim and the exit status is still the command's. This is the recommended form for -any programmatic call whose stderr matters, which is most of them. - -Note what the workaround is not. `dl ws -- make test 2>&1` merges on the *host*, after -the mangling has already happened, and gives you the logger's version of stderr mixed -into good stdout. The redirection has to be inside the command `dl` is asked to run. - ## The unit of isolation is the branch A workspace id is derived from the `(owner, repo, branch)` triple, so one branch is one diff --git a/rust/aid/tests/interactive.rs b/rust/aid/tests/interactive.rs index f9bc1bfc..82027ffd 100644 --- a/rust/aid/tests/interactive.rs +++ b/rust/aid/tests/interactive.rs @@ -325,7 +325,7 @@ fn a_typed_prompt_reaches_the_agent_with_no_shell_in_the_way() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ + "devpod ssh {MAIN} --log-output json --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN} \ '\"'\"'fix the \"flaky\" test'\"'\"''" ) @@ -350,7 +350,7 @@ fn a_pasted_multi_line_prompt_arrives_whole_rather_than_leaking() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ + "devpod ssh {MAIN} --log-output json --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN} \ '\"'\"'fix this\nand then that'\"'\"''" ) @@ -367,7 +367,7 @@ fn an_empty_enter_is_the_plain_session_it_always_was() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ + "devpod ssh {MAIN} --log-output json --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN}'" ) ); @@ -396,7 +396,7 @@ fn the_boot_runs_while_the_prompt_is_still_being_typed() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ + "devpod ssh {MAIN} --log-output json --command bash -lc 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN} go'" ) ); diff --git a/rust/aid/tests/rewrite.rs b/rust/aid/tests/rewrite.rs index a17f72bf..93fbaf82 100644 --- a/rust/aid/tests/rewrite.rs +++ b/rust/aid/tests/rewrite.rs @@ -289,7 +289,7 @@ fn a_prompt_reaches_the_agent_as_one_argument_through_dls_own_launch() { IS_SANDBOX=1 claude --dangerously-skip-permissions \ --remote-control=devlaunch-main-3j1t 'fix the bug'", "Workspace devlaunch-main-3j1t is already running, attaching...", - "SSH command: devpod ssh devlaunch-main-3j1t --command bash -lc \ + "SSH command: devpod ssh devlaunch-main-3j1t --log-output json --command bash -lc \ 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control=devlaunch-main-3j1t \ '\"'\"'fix the bug'\"'\"''", @@ -300,7 +300,7 @@ fn a_prompt_reaches_the_agent_as_one_argument_through_dls_own_launch() { [ format!("devpod status {MAIN} --output json"), format!( - "devpod ssh {MAIN} --command bash -lc \ + "devpod ssh {MAIN} --log-output json --command bash -lc \ 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN} \ '\"'\"'fix the bug'\"'\"''" @@ -321,7 +321,7 @@ fn no_remote_control_is_the_one_way_back_to_a_purely_local_session() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc \ + "devpod ssh {MAIN} --log-output json --command bash -lc \ 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions hi'" ), @@ -361,7 +361,7 @@ fn an_appended_off_switch_is_observed_from_outside_to_turn_it_off() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc \ + "devpod ssh {MAIN} --log-output json --command bash -lc \ 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions '\"'\"'fix the bug'\"'\"''" ) @@ -401,7 +401,7 @@ fn no_prompt_starts_the_agents_plain_session() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc \ + "devpod ssh {MAIN} --log-output json --command bash -lc \ 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN}'" ) @@ -445,7 +445,7 @@ fn each_agent_is_started_the_way_its_own_cli_takes_a_prompt() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc 'gemini --yolo --prompt-interactive '\"'\"'explain this'\"'\"''" + "devpod ssh {MAIN} --log-output json --command bash -lc 'gemini --yolo --prompt-interactive '\"'\"'explain this'\"'\"''" ) ); @@ -453,7 +453,7 @@ fn each_agent_is_started_the_way_its_own_cli_takes_a_prompt() { bare.aid(&["--gemini", MAIN]).exited(0); assert_eq!( bare.devpod_calls().last().expect("a session"), - &format!("devpod ssh {MAIN} --command bash -lc 'gemini --yolo'") + &format!("devpod ssh {MAIN} --log-output json --command bash -lc 'gemini --yolo'") ); // codex is the one agent whose payload carries a prefix, because it is the one @@ -487,7 +487,7 @@ fn remote_control_reaches_claude_as_one_named_flag_and_dl_never_sees_it() { assert_eq!( world.devpod_calls().last().expect("a session"), &format!( - "devpod ssh {MAIN} --command bash -lc \ + "devpod ssh {MAIN} --log-output json --command bash -lc \ 'CLAUDE_CODE_DISABLE_TERMINAL_TITLE=1 IS_SANDBOX=1 claude \ --dangerously-skip-permissions --remote-control={MAIN} '\"'\"'fix the bug'\"'\"''" ) diff --git a/rust/devlaunch-core/src/clients/devpod.rs b/rust/devlaunch-core/src/clients/devpod.rs index 842f666d..2c266588 100644 --- a/rust/devlaunch-core/src/clients/devpod.rs +++ b/rust/devlaunch-core/src/clients/devpod.rs @@ -390,8 +390,83 @@ const REMOTE_EXIT_MARKER: &str = "ssh session: Process exited with status "; /// devpod's own level tag, which the report has to be anchored on as well: a /// remote program printing the same sentence on its own stderr (which reaches /// devlaunch only when there is no pty) must not be mistaken for devpod's report. +/// +/// The same word is devpod's `level` field in json, which is why one constant +/// serves both readings in [`StderrFilter::push`]. const FATAL_TAG: &str = "fatal"; +/// Ask devpod's logger for json instead of its decorated plain lines. +/// +/// A global flag of devpod's, taking `plain` (the default), `raw` or `json`, and +/// it belongs *here* rather than at the call site because the flag and +/// [`StderrFilter`]'s parsing are one fact: devpod's stderr is in the shape this +/// asked for, and the reader is two screens away from the ask. +/// +/// Why this exists at all: without a pty, the command's own stderr comes back +/// through devpod's stream logger rather than as itself. Measured against +/// devpod 0.26.1, `echo ERR >&2` in a container arrives as +/// +/// ```text +/// [0;1;37m19:54:56[0m [0;1;36minfo[0m ERR [0;90mstream_logger.go:492[0m +/// ``` +/// +/// -- timestamped, level-tagged, coloured, with a Go source location appended. +/// That is unparsable as a compiler's or a test runner's diagnostics, which is +/// what `docs/agents-using-dl.md` promises a caller gets. In json the same line +/// is `{"time":"...","message":"ERR","level":"info"}`, and the message is the +/// command's bytes, so the decoration can be taken back off. +/// +/// **`raw` was measured and rejected**, though it is the obvious choice: it emits +/// the bare message and nothing else, including no level. devpod's report of a +/// remote exit status is then +/// `tunnel to container: run in container: ssh session: Process exited with +/// status 42` with no `fatal` in it, [`recovered_status`] returns `None`, and +/// `dl ws -- 'exit 42'` stops exiting 42 -- the *first* clause of the same +/// contract, silently traded for the last one. json keeps the level as a field, +/// which is both a stronger anchor than a coloured tag and a thing the remote +/// program cannot forge: devpod wraps whatever the container writes in a record +/// of its own at `info`, escaping it, so a container printing a whole fatal +/// record verbatim arrives as that record's `message` (measured). +/// +/// `--silent` is the other neighbour and is wrong for a different reason: it +/// suppresses everything below a fatal, which includes the command's stderr. +pub(crate) const JSON_LOG_ARGS: [&str; 2] = ["--log-output", "json"]; + +/// One line of devpod's stderr under [`JSON_LOG_ARGS`]. +/// +/// Both fields are required, which is the whole of what keeps a JSON *document* +/// on the stream from being read as a log record: a container running +/// `cat report.json 1>&2` under a devpod too old to know `--log-output` would +/// otherwise have its lines silently relabelled. `time` is devpod's third field +/// and is dropped -- nothing here has a use for it, and the line's arrival is +/// already the only timing this filter reports on. +#[derive(serde::Deserialize)] +struct LogRecord { + /// devpod's own level word: `debug`, `info`, `warn`, `error`, `fatal`. + level: String, + /// What the plain formatter would have printed between the level and the Go + /// source location, with none of that decoration on it. + message: String, +} + +impl LogRecord { + /// Read `line` as a record, or `None` if it is not one. + /// + /// A miss is the ordinary case, not a failure: it is every line from a devpod + /// that does not know `--log-output`, from the pty route where the flag is not + /// passed at all, and from the attach route's plain log. The caller falls back + /// to the plain-text predicates, which is the behaviour this module had before + /// json was asked for. + fn parse(line: &str) -> Option { + // Cheap enough to skip for a line that cannot be an object, and it keeps + // serde_json off every line of an ordinary plain-mode session. + if !line.trim_start().starts_with('{') { + return None; + } + serde_json::from_str(line).ok() + } +} + /// Forward devpod's stderr, holding back its report of a remote exit status. /// /// Stateful because it is fed one line at a time as the session runs: the @@ -410,24 +485,48 @@ impl StderrFilter { /// Feed one line, forwarding whatever the user should see. /// - /// Lines arrive without their newline — the runner strips it — and are - /// forwarded exactly as they came, because everything devpod says for its own - /// sake must read as it does today. + /// Lines arrive without their newline — the runner strips it. + /// + /// Two readings, tried in that order. Under [`JSON_LOG_ARGS`] the line is a + /// record, and then the level is devpod's own field rather than a coloured + /// tag to be regexed, and what gets forwarded is the bare `message` — which + /// for a command's stderr is the command's bytes and nothing else, and for + /// devpod's own warnings is the sentence without its timestamp and Go source + /// location. A line that is not a record is read exactly as this module read + /// every line before json was asked for, so a devpod too old to know the flag, + /// the pty route that is not given it, and anything on the stream that is not + /// a log line at all all behave as they did. pub(crate) fn push(&mut self, line: &str, forward: &mut dyn FnMut(&str)) { - if let Some(status) = recovered_status(line) { + let record = LogRecord::parse(line); + // What the user should see of this line: the message alone when devpod + // told us which part of it that is. + let text = record + .as_ref() + .map_or(line, |record| record.message.as_str()); + let status = match &record { + // No word-boundary dance on this path: `level` is a field devpod + // filled in, and the container's own stderr arrives as the `message` + // of a record at `info`, so it cannot reach here claiming `fatal`. + Some(record) if record.level == FATAL_TAG => remote_status_in(text), + Some(_) => None, + None => recovered_status(line), + }; + if let Some(status) = status { self.remote_status = Some(status); // The hint introduced this fatal, so it goes with it. self.held_hint = None; return; } - if line.contains(DEBUG_HINT) { - self.held_hint = Some(line.to_owned()); + // Matched against `text` rather than the raw line so the hold-back keeps + // working in json, where the hint is a record like any other. + if text.contains(DEBUG_HINT) { + self.held_hint = Some(text.to_owned()); return; } if let Some(hint) = self.held_hint.take() { forward(&hint); } - forward(line); + forward(text); } /// The stream ended: release a hint nothing followed, and report the status @@ -453,20 +552,32 @@ fn recovered_status(line: &str) -> Option { if !boundary_before(&line[after_tag..]) { continue; } - let rest = &line[after_tag..]; - for (marker_at, _) in rest.match_indices(REMOTE_EXIT_MARKER) { - if !boundary_after(&rest[..marker_at]) { - continue; - } - let digits: String = rest[marker_at + REMOTE_EXIT_MARKER.len()..] - .chars() - .take_while(char::is_ascii_digit) - .collect(); - // A count too large for an exit status is not a status anything - // could have exited with, so it is not devpod reporting one. - if let Ok(status) = digits.parse::() { - return Some(status); - } + if let Some(status) = remote_status_in(&line[after_tag..]) { + return Some(status); + } + } + None +} + +/// The remote exit status the x/crypto sentence reports somewhere in `text`. +/// +/// Split out of [`recovered_status`] because json needs this half and not the +/// other: the `fatal` the plain reading has to find in the text is a field there, +/// already read, and searching the message for the word again would let a command +/// whose own stderr says "fatal" back into a decision devpod had already made. +fn remote_status_in(text: &str) -> Option { + for (marker_at, _) in text.match_indices(REMOTE_EXIT_MARKER) { + if !boundary_after(&text[..marker_at]) { + continue; + } + let digits: String = text[marker_at + REMOTE_EXIT_MARKER.len()..] + .chars() + .take_while(char::is_ascii_digit) + .collect(); + // A count too large for an exit status is not a status anything + // could have exited with, so it is not devpod reporting one. + if let Ok(status) = digits.parse::() { + return Some(status); } } None @@ -508,9 +619,14 @@ pub(crate) fn interpret(devpod_exit: Exit, remote_status: Option) -> SshOut /// /// stdin and stdout are inherited untouched — devpod puts the real terminal into /// raw mode through them and requests a pty on that basis, so a pipe on either -/// changes what devpod does. Only stderr is read, which under a pty carries -/// devpod's own warnings and nothing else, so its report of how the session -/// ended can be interpreted rather than dumped on the user. +/// changes what devpod does. Only stderr is read, so devpod's report of how the +/// session ended can be interpreted rather than dumped on the user. +/// +/// What else is on that stream depends on the pty. Under one, devpod's own +/// warnings and nothing else: the container's stderr goes down the pty with +/// everything else. Without one — `devpod ssh --command`, which is every +/// scripted call — the container's stderr is on it too, wrapped by devpod's +/// logger, and [`JSON_LOG_ARGS`] is what lets [`StderrFilter`] unwrap it. /// /// `forward` is where the lines that *should* be seen go. Python writes them to /// `sys.stderr` from inside the filter; core writes to nobody's stream, so the @@ -1606,6 +1722,119 @@ mod tests { ); } + // ------------------------------------ the same stream under --log-output json + + /// The records devpod 0.26.1 emits under [`JSON_LOG_ARGS`], verbatim from the + /// measurement: `dl -- sh -c 'echo ERR >&2'` and `-- sh -c 'exit 42'`. + /// Field order is devpod's, and nothing here depends on it. + const JSON_COMMAND_STDERR: &str = + r#"{"time":"2026-09-14T20:22:21.813127762+01:00","message":"ERR","level":"info"}"#; + const JSON_REMOTE_EXIT: &str = concat!( + r#"{"time":"2026-09-14T20:22:37.481720628+01:00","message":"tunnel to container: "#, + r#"run in container: ssh session: Process exited with status 42","level":"fatal"}"#, + ); + + #[test] + fn a_commands_stderr_arrives_as_the_command_wrote_it() { + // The whole point of the flag. Under plain this line is the timestamp, the + // `info` tag, the text, and `stream_logger.go:492`, none of which a caller + // parsing a compiler can see past. + let (status, shown) = filter(&[JSON_COMMAND_STDERR]); + + assert_eq!(status, None); + assert_eq!(shown, vec!["ERR".to_owned()]); + } + + #[test] + fn the_buried_status_is_read_off_the_level_field() { + let (status, shown) = filter(&[JSON_REMOTE_EXIT]); + + assert_eq!(status, Some(42)); + assert!(shown.is_empty(), "nothing has gone wrong: {shown:?}"); + assert_eq!( + interpret(Exit::Code(1), status), + SshOutcome::RemoteExit { status: 42 } + ); + } + + #[test] + fn a_command_printing_a_fatal_record_of_its_own_is_not_devpods_report() { + // The attack the plain reading has to work for with word boundaries, and + // which json answers structurally: devpod escapes the container's line into + // the `message` of a record at `info` (measured), so the level the filter + // reads is devpod's own and the sentence inside is just text. + let line = concat!( + r#"{"time":"2026-09-14T20:23:45.31230689+01:00","message":"#, + r#""{\"level\":\"fatal\",\"message\":\"ssh session: Process exited with "#, + r#"status 7\"}","level":"info"}"#, + ); + + let (status, shown) = filter(&[line]); + + assert_eq!(status, None, "a container cannot forge devpod's level"); + assert_eq!( + shown, + vec![ + r#"{"level":"fatal","message":"ssh session: Process exited with status 7"}"# + .to_owned() + ], + "and its line still comes back as it wrote it" + ); + } + + #[test] + fn devpods_own_warnings_lose_their_decoration_and_nothing_else() { + let line = r#"{"time":"2026-09-14T20:22:21Z","message":"workspace is already running","level":"warn"}"#; + + let (status, shown) = filter(&[line]); + + assert_eq!(status, None); + assert_eq!(shown, vec!["workspace is already running".to_owned()]); + } + + #[test] + fn the_debug_hint_is_still_held_back_when_it_arrives_as_a_record() { + // The hold-back is matched against the message, not the raw line, or the + // hint would be forwarded on the json path and then the fatal it + // introduces would be swallowed -- a hint with nothing under it. + let hint = format!( + r#"{{"time":"2026-09-14T20:22:37Z","message":"{DEBUG_HINT}","level":"error"}}"# + ); + + let (status, shown) = filter(&[&hint, JSON_REMOTE_EXIT]); + + assert_eq!(status, Some(42)); + assert!(shown.is_empty(), "{shown:?}"); + } + + #[test] + fn a_json_document_on_the_stream_is_not_read_as_a_log_record() { + // `dl ws -- cat report.json 1>&2` against a devpod that does not know + // `--log-output`. Both of devpod's fields are required, so an object + // holding neither is forwarded whole rather than silently relabelled. + let lines = [ + r#"{"level":"fatal"}"#, + r#"{"message":"hello"}"#, + r#"{"kind":"summary","failures":0}"#, + "{ not json at all", + ]; + + let (status, shown) = filter(&lines); + + assert_eq!(status, None); + assert_eq!(shown, lines.map(str::to_owned).to_vec()); + } + + #[test] + fn a_plain_devpod_is_read_exactly_as_it_was_before() { + // The fallback, asked of the two lines that matter: a devpod too old to + // know the flag, and the attach route, which is not given it. + let (status, shown) = filter(&[DEBUG_HINT_LINE, REMOTE_EXIT_LINE]); + + assert_eq!(status, Some(130)); + assert!(shown.is_empty(), "{shown:?}"); + } + #[test] fn a_session_holds_back_the_report_it_recovers_and_answers_with_it() { let fake = ScriptedRunner::new().with_script( diff --git a/rust/devlaunch-core/src/flows/launch.rs b/rust/devlaunch-core/src/flows/launch.rs index 4c193d4f..eb4a67e9 100644 --- a/rust/devlaunch-core/src/flows/launch.rs +++ b/rust/devlaunch-core/src/flows/launch.rs @@ -2970,6 +2970,25 @@ fn devpod_session( args.push(workdir.to_owned()); } if let Some(payload) = payload { + // A command, so devpod asks for no pty, so the *container's* stderr comes + // back on devpod's stderr with devpod's stream logger wrapped around it. + // json is how it comes back off again: [`devpod::JSON_LOG_ARGS`] carries + // the measurement and why `raw` is a trap. + // + // Scoped to this arm deliberately. A bare attach (no payload) gets a pty, + // and under one the container's stderr never touches this stream -- the + // only thing json would change there is the look of devpod's own warnings + // to the person sitting in front of them, trading a coloured `warn` tag + // for nothing. So an interactive `dl ` logs exactly as it did, and the + // flag goes only where there is something to unwrap. + // + // After the workspace id, never before it: `flows::session_manager`'s + // `workspace_named_by` reads an id out of `devpod ssh ` by position, + // and a flag in front of it would make every session anonymous to the + // manager. `both_transports_name_the_workspace_they_were_built_for` runs + // this builder and would catch it, which is the test to look at if this + // argv is ever reordered. + args.extend(devpod::JSON_LOG_ARGS.iter().map(|arg| (*arg).to_owned())); args.push("--command".to_owned()); args.push(payload.as_str().to_owned()); } @@ -9264,6 +9283,33 @@ mod tests { ); } + #[test] + fn a_command_asks_devpod_to_log_in_json_and_an_attach_does_not() { + // The two halves of the scoping decision, side by side, because the + // difference between them is the whole of it. A command gets no pty, so + // the container's stderr comes back through devpod's stream logger and + // json is what lets `clients::devpod`'s filter unwrap it. An attach gets + // one, the container's stderr never touches that stream, and the only + // thing json would change is the look of devpod's own warnings to the + // person reading them. + let scene = Scene::new().with_running("myws"); + + let (_, _, _) = a_session(&scene, Some(&RemoteCommand::argv(&["echo", "hi"]))); + assert!( + scene.devpod_commands()[0].contains(&"--log-output".to_owned()), + "{:?}", + scene.devpod_commands() + ); + + let attaching = Scene::new().with_running("myws"); + let (_, _, _) = a_session(&attaching, None); + assert_eq!( + attaching.devpod_commands(), + vec![vec!["ssh".to_owned(), "myws".to_owned()]], + "an interactive attach logs exactly as it did" + ); + } + #[test] fn a_one_shot_command_travels_as_the_shlex_quoted_payload() { let scene = Scene::new().with_running("myws"); @@ -9276,6 +9322,8 @@ mod tests { vec![vec![ "ssh".to_owned(), "myws".to_owned(), + "--log-output".to_owned(), + "json".to_owned(), "--command".to_owned(), "bash -lc 'echo hi'".to_owned(), ]] @@ -9464,6 +9512,8 @@ mod tests { "devpod".to_owned(), "ssh".to_owned(), "myws".to_owned(), + "--log-output".to_owned(), + "json".to_owned(), "--command".to_owned(), "bash -lc 'echo hi'".to_owned(), ] @@ -9966,7 +10016,10 @@ mod tests { vec!["ssh".to_owned(), "myws".to_owned()], ] ); - assert!(commands[1][3].contains("chezmoi update"), "{commands:?}"); + // `ssh myws --log-output json --command `: the payload is the + // sixth word, and the json flag is on the refresh because it is a command + // and not the attach below it. + assert!(commands[1][5].contains("chezmoi update"), "{commands:?}"); assert_eq!(commands[2], vec!["ssh".to_owned(), "myws".to_owned()]); } @@ -9992,6 +10045,8 @@ mod tests { vec![vec![ "ssh".to_owned(), "myws".to_owned(), + "--log-output".to_owned(), + "json".to_owned(), "--command".to_owned(), "bash -lc 'echo hi'".to_owned(), ]] @@ -11247,6 +11302,8 @@ mod tests { vec![ "ssh".to_owned(), workspace.value().to_owned(), + "--log-output".to_owned(), + "json".to_owned(), "--command".to_owned(), "bash -lc 'echo hi'".to_owned(), ], diff --git a/rust/dl/tests/launch.rs b/rust/dl/tests/launch.rs index e336a95a..ffb66b63 100644 --- a/rust/dl/tests/launch.rs +++ b/rust/dl/tests/launch.rs @@ -514,13 +514,13 @@ fn a_command_travels_as_one_quoted_bash_lc_payload() { run.exited(0); assert_eq!( run.stderr_lines()[1], - format!("SSH command: devpod ssh {MAIN} --command bash -lc 'echo hi'") + format!("SSH command: devpod ssh {MAIN} --log-output json --command bash -lc 'echo hi'") ); assert_eq!( world.calls().exact(&world.root), [ format!("devpod status {MAIN} --output json"), - format!("devpod ssh {MAIN} --command bash -lc 'echo hi'"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'echo hi'"), ] ); } @@ -544,7 +544,7 @@ fn a_quoted_prompt_reaches_the_agent_intact() { assert_eq!( world.calls().exact(&world.root).last(), Some(&format!( - "devpod ssh {MAIN} --command bash -lc \ + "devpod ssh {MAIN} --log-output json --command bash -lc \ 'claude '\"'\"'it'\"'\"'\"'\"'\"'\"'\"'\"'s here'\"'\"''" )) ); @@ -563,7 +563,7 @@ fn the_zellij_opt_in_puts_a_session_beside_the_command() { assert_eq!( run.stderr_lines()[1], format!( - "SSH command: devpod ssh {MAIN} --command bash -lc 'zellij attach -b devlaunch \ + "SSH command: devpod ssh {MAIN} --log-output json --command bash -lc 'zellij attach -b devlaunch \ >/dev/null 2>&1 || true; claude '\"'\"'fix it'\"'\"''" ) ); @@ -628,7 +628,7 @@ fn a_warm_triple_launch_writes_nothing_to_the_cache() { world.calls().exact(&world.root), [ format!("devpod status {MAIN} --output json"), - format!("devpod ssh {MAIN} --command bash -lc 'echo hi'"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'echo hi'"), ] ); } @@ -703,7 +703,7 @@ fn the_dotfiles_opt_in_refreshes_in_front_of_an_interactive_shell() { // command in its own process group, so the git or pixi process actually // waiting dies with the shell that started it rather than holding the // session open. - format!("devpod ssh {MAIN} --command bash -lc 'timeout 60 bas…"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'timeout 60 bas…"), format!("devpod ssh {MAIN}"), ] ); @@ -725,7 +725,7 @@ fn a_one_shot_command_is_not_worth_a_dotfiles_refresh() { world.calls().exact(&world.root), [ format!("devpod status {MAIN} --output json"), - format!("devpod ssh {MAIN} --command bash -lc 'echo hi'"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'echo hi'"), ] ); } @@ -1176,7 +1176,7 @@ fn dotfiles_refreshes_a_running_workspace_without_bringing_anything_up() { // Then the context options the refresh's fallback clone URL comes from, // and one session carrying the refresh. "devpod context options --output json".to_owned(), - format!("devpod ssh {MAIN} --command bash -lc 'if command -v …"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'if command -v …"), ] ); // Unbounded, unlike the refresh nobody asked for: this one is typed, in the @@ -1209,7 +1209,7 @@ fn dotfiles_starts_a_stopped_workspace_first_and_says_so() { assert!( calls.iter().any(|call| { call.starts_with(&format!( - "devpod ssh {MAIN} --command bash -lc 'if command -v " + "devpod ssh {MAIN} --log-output json --command bash -lc 'if command -v " )) }), "the dotfiles refresh did not run: {calls:?}" @@ -1291,7 +1291,7 @@ fn a_path_spec_dotfiles_asks_once_and_brings_nothing_up() { [ format!("devpod status {MAIN} --output json"), "devpod context options --output json".to_owned(), - format!("devpod ssh {MAIN} --command bash -lc 'if command -v …"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'if command -v …"), ] ); } @@ -1332,7 +1332,7 @@ fn a_path_spec_attach_asks_nothing_and_ups() { .to_owned(), format!("devpod ssh {MAIN} --command bash -lc 'if sudo hostna…"), format!("devpod ssh {MAIN} --command bash -lc 'set -u…"), - format!("devpod ssh {MAIN} --command bash -lc true"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc true"), ] ); assert_eq!( @@ -1370,7 +1370,7 @@ fn a_cold_triple_dotfiles_denies_the_same_id_twice() { .to_owned(), format!("devpod ssh {COLD} --command bash -lc 'if sudo hostna…"), format!("devpod ssh {COLD} --command bash -lc 'set -u…"), - format!("devpod ssh {COLD} --command bash -lc 'if command -v …"), + format!("devpod ssh {COLD} --log-output json --command bash -lc 'if command -v …"), ] ); } @@ -1412,7 +1412,7 @@ fn a_path_spec_dotfiles_on_a_stopped_workspace_ups_it_by_id() { .to_owned(), format!("devpod ssh {MAIN} --command bash -lc 'if sudo hostna…"), format!("devpod ssh {MAIN} --command bash -lc 'set -u…"), - format!("devpod ssh {MAIN} --command bash -lc 'if command -v …"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'if command -v …"), ] ); // Byte-exact, because the summary above clips the two flags this row exists for. @@ -2008,7 +2008,7 @@ fn rm_on_exit_runs_the_command_first_and_removes_the_workspace_after_it() { world.calls().exact(&world.root), [ format!("devpod status {MAIN} --output json"), - format!("devpod ssh {MAIN} --command bash -lc 'echo hi'"), + format!("devpod ssh {MAIN} --log-output json --command bash -lc 'echo hi'"), format!("devpod status {MAIN} --output json"), format!("devpod delete {MAIN}"), ] diff --git a/test/e2e/test_agent_subprocess_contract.py b/test/e2e/test_agent_subprocess_contract.py index 45b5234d..885687ed 100644 --- a/test/e2e/test_agent_subprocess_contract.py +++ b/test/e2e/test_agent_subprocess_contract.py @@ -14,7 +14,8 @@ contract. `test/test_agent_contract_doc.py` is the other half of the pairing: it holds the page to still making the claims these tests are the evidence for. -The stderr clause is the interesting one and it is an `xfail`. See +The stderr clause was the interesting one, and until devlaunch passed +`--log-output json` to `devpod ssh` it was a strict `xfail`. See `test_stderr_is_the_commands_output_verbatim`. """ @@ -219,12 +220,13 @@ def test_no_terminal_is_required(piped): @pytest.mark.e2e def test_merging_inside_the_container_is_a_working_recipe(piped): - """The workaround `docs/agents-using-dl.md` tells a caller to use. + """The merge `docs/agents-using-dl.md` still shows, no longer as a workaround. - It is documented, so it is tested: both lines arrive on stdout, in the right - order, with nothing between them, and the exit status still belongs to the - command. If this breaks, the page is telling callers to do something that does - not work, which is worse than the mangling it routes around. + It was the route around the mangled stderr and it outlived the mangling: a + caller who wants one interleaved stream rather than two streams still wants + this, so the page keeps it and this keeps the page honest. Both lines arrive on + stdout, in the right order, with nothing between them, and the exit status + still belongs to the command. """ result = piped.run("sh", "-c", f"{{ echo {MARKER}-out; echo {MARKER}-err >&2; }} 2>&1; exit 3") assert result.returncode == 3, _shows(result) @@ -234,23 +236,21 @@ def test_merging_inside_the_container_is_a_working_recipe(piped): @pytest.mark.e2e -@pytest.mark.xfail( - strict=True, - reason=( - "devpod's stream logger reformats the command's stderr on the way out: it " - "arrives timestamped, level-prefixed, ANSI-coloured and with a Go source " - "location appended. docs/agents-using-dl.md documents the `2>&1` workaround " - "instead. This xfail is strict so that fixing the transport turns the suite " - "red and the page's workaround section gets removed in the same change." - ), -) def test_stderr_is_the_commands_output_verbatim(piped): - """The clause the contract does not yet keep, written as the contract wants it. - - Deliberately not written as an assertion that the mangling happens. A test that - pins current behaviour makes the bug part of the spec and quietly outlives the - fix; a strict xfail of the *desired* behaviour fails the day it starts working, - which is the day the documentation has to change. + """Clause five, which was a strict xfail until the transport kept it. + + It was written as the contract wanted rather than as the mangling behaved, + deliberately: a test that pins current behaviour makes the bug part of the spec + and quietly outlives the fix, where a strict xfail of the *desired* behaviour + fails the day it starts working. That day was `--log-output json` on the + `devpod ssh` invocation (`clients/devpod.rs`'s `JSON_LOG_ARGS`), which turns + devpod's stream logger into records dl can unwrap instead of decoration dl + would have to regex. + + `endswith` rather than equality because dl's own narration is on this stream + too, ahead of the command. That it is only ahead is what + `test_the_launch_narration_is_on_stderr_where_a_caller_can_ignore_it` and the + stdout clause between them pin. """ result = piped.run("sh", "-c", f"echo {MARKER} >&2") assert result.returncode == 0, _shows(result) @@ -259,6 +259,26 @@ def test_stderr_is_the_commands_output_verbatim(piped): ) +@pytest.mark.e2e +def test_a_commands_stderr_carries_no_log_decoration_at_all(piped): + """The other half of clause five: not just the tail, the whole of it. + + `endswith` above passes on a line devpod prefixed with a timestamp and a level, + which is exactly the mangling this clause is about, so the shape of the wrapper + is asserted absent by name. `stream_logger.go` is the Go source location the + plain formatter appended; `\x1b[` is the colour it wrapped the tag in; and + a bare `\n` before the marker is what says nothing was glued to its front. + """ + result = piped.run("sh", "-c", f"echo {MARKER} >&2") + assert result.returncode == 0, _shows(result) + assert "stream_logger.go" not in result.stderr, ( + f"devpod's stream logger is still decorating stderr{_shows(result)}" + ) + assert f"\n{MARKER}\n" in result.stderr or result.stderr == f"{MARKER}\n", ( + f"something was prefixed to the command's stderr line{_shows(result)}" + ) + + @pytest.mark.e2e def test_the_launch_narration_is_on_stderr_where_a_caller_can_ignore_it(piped): """The other side of clause two: the chatter exists, and it has a home. diff --git a/test/test_agent_contract_doc.py b/test/test_agent_contract_doc.py index 1ae57b6e..45671d1d 100644 --- a/test/test_agent_contract_doc.py +++ b/test/test_agent_contract_doc.py @@ -1,12 +1,18 @@ """The contract `docs/agents-using-dl.md` publishes, and the `--help` line that sends a reader to it. -The page states four properties of `dl -- ` that a caller writes code -against: the exit status is the command's, stdout is the command's, stdin reaches it, -and none of that needs a terminal. All four held before the page existed, which is -exactly why they needed writing down and then guarding. A promise nothing states is a -promise a refactor cannot see it is breaking, and the caller who finds out is a script -somewhere else that now reads `dl`'s progress chatter as its JSON. +The page states five properties of `dl -- ` that a caller writes code +against: the exit status is the command's, stdout is the command's, stderr is the +command's, stdin reaches it, and none of that needs a terminal. Four of them held +before the page existed, which is exactly why they needed writing down and then +guarding. A promise nothing states is a promise a refactor cannot see it is breaking, +and the caller who finds out is a script somewhere else that now reads `dl`'s progress +chatter as its JSON. + +The fifth is the one the page had to wait for. stderr came back through devpod's stream +logger, timestamped and level-tagged and coloured, and the page carried a section saying +so next to a `2>&1` workaround. `--log-output json` on the `devpod ssh` invocation is +what closed it; the phrase below is what stops the clause quietly going back out again. The behaviour itself is pinned in `test/e2e/test_agent_subprocess_contract.py`, which needs a Docker daemon and is skipped by default. What is guarded *here* is everything @@ -69,6 +75,7 @@ PROMISES = { "exit status": "exit status is the command's", "stdout": "stdout is the command's, verbatim", + "stderr": "stderr is the command's too", "stdin": "stdin is the command's", "no terminal": "No terminal is required", }