feat(observability): stream a microVM turn's stdout/stderr to the platform live
The Live tab showed nothing while a turn ran, and the agent's own account of it
went to stderr on the node and nowhere a user could reach. This is the path that
carries it.
The blocker was the guest agent. `fcagent` handled one connection at a time,
inline, so during an hour-long turn the VM accepted nothing — which is why every
existing probe (subagents, stop-gate blocks, cap) runs AFTER the turn rather than
during it. It now spawns a thread per connection, wrapped in `catch_unwind`
because this process is pid 1: a panic used to take the accept loop with it, and
an unbootable VM is a far worse outcome than a missing log. A failed spawn logs
and keeps accepting rather than dropping the listener.
PROVED against a live VM before building on it, since "sound reasoning about this
system" and "measurement" have diverged repeatedly today. Patched rootfs, booted
under Firecracker, ran an 8s exec and a concurrent tail:
exec took 8.0s ok=True
+0.0s 'line1\nline2\n' +1.2s 'line4\n' +3.2s 'line6\n' +6.0s 'DONE\n'
VERDICT: CONCURRENT — tail returned data before exec finished
The rest is the pattern the terminal already uses. New `tail` op streams a file
by OFFSET (so a dropped link resumes instead of replaying, and the tail always
terminates — one that never returns pins a thread for the life of the VM). The
node follows the log alongside the turn and pushes `Uplink::VmOut { run_id, at,
data }` over the WebSocket it already holds, mirroring `PtyOut`. The server does
what `PtyOut` deliberately does not: it APPENDS to the run's checkpoint as well
as fanning out, because a terminal has no history worth keeping and a mission log
is the record of what the agent did. `run_events_sse` emits the new bytes as
`step` events, which the live pane already renders — no frontend change.
The turn is `tee`d, not redirected: the file feeds the live stream and stdout
still becomes `VmOutcome::summary`. A redirect would have produced a live view
and an empty summary, which is the same green-and-empty shape as the bug this
fixes. Tested, along with the log living outside the collected tree so it never
lands in a user's delivered diff.
246 lib tests, 20 binaries; node and fcagent build clean.
This commit is contained in:
@@ -104,11 +104,41 @@ fn main() {
|
||||
for conn in listener.incoming() {
|
||||
match conn {
|
||||
Ok(mut s) => {
|
||||
if let Err(e) = serve_one(&mut s) {
|
||||
// A bad request must never kill the agent — the VM would
|
||||
// look booted and answer nothing, the worst of both.
|
||||
eprintln!("FC-AGENT-ERROR {e}");
|
||||
}
|
||||
// One THREAD per connection, not one at a time.
|
||||
//
|
||||
// This loop used to call `serve_one` inline, which meant the
|
||||
// agent accepted nothing while an op was running. A mission turn
|
||||
// is an `exec` that can last an hour, so for that hour the guest
|
||||
// was unreachable: the host could not tail its output, probe it,
|
||||
// or ask it anything. Every existing probe runs AFTER the turn
|
||||
// for exactly this reason.
|
||||
//
|
||||
// A thread rather than async: this is a static musl binary with
|
||||
// no runtime, and the concurrency here is a handful of
|
||||
// connections, not thousands.
|
||||
//
|
||||
// The panic discipline of the old inline call still applies, and
|
||||
// matters MORE now — this process is pid 1, and a panic that
|
||||
// unwound out of a worker used to take the accept loop with it.
|
||||
// `catch_unwind` keeps a bad request from killing the VM.
|
||||
std::thread::Builder::new()
|
||||
.name("fcagent-conn".into())
|
||||
.spawn(move || {
|
||||
let r = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
|
||||
serve_one(&mut s)
|
||||
}));
|
||||
match r {
|
||||
Ok(Err(e)) => eprintln!("FC-AGENT-ERROR {e}"),
|
||||
Err(_) => eprintln!("FC-AGENT-ERROR handler panicked"),
|
||||
Ok(Ok(())) => {}
|
||||
}
|
||||
})
|
||||
.map(|_| ())
|
||||
.unwrap_or_else(|e| {
|
||||
// Out of threads: answer nothing on this connection, but
|
||||
// keep accepting. Dropping the listener would brick the VM.
|
||||
eprintln!("FC-AGENT-ERROR spawn: {e}");
|
||||
});
|
||||
}
|
||||
Err(e) => eprintln!("FC-AGENT-ERROR accept: {e}"),
|
||||
}
|
||||
@@ -227,13 +257,94 @@ fn serve_one(s: &mut vsock::VsockStream) -> Result<(), String> {
|
||||
s.read_exact(&mut buf)
|
||||
.map_err(|e| format!("read body: {e}"))?;
|
||||
|
||||
let resp = match serde_json::from_slice::<Value>(&buf) {
|
||||
Ok(req) => handle(&req),
|
||||
Err(e) => json!({ "ok": false, "error": format!("undecodable request: {e}") }),
|
||||
let req = match serde_json::from_slice::<Value>(&buf) {
|
||||
Ok(req) => req,
|
||||
Err(e) => {
|
||||
return reply(
|
||||
s,
|
||||
&json!({ "ok": false, "error": format!("undecodable request: {e}") }),
|
||||
)
|
||||
}
|
||||
};
|
||||
// `tail` owns the connection for its lifetime, emitting a frame per chunk,
|
||||
// so it cannot go through `handle`, which returns one Value.
|
||||
if req.get("op").and_then(Value::as_str) == Some("tail") {
|
||||
return op_tail(s, &req);
|
||||
}
|
||||
let resp = handle(&req);
|
||||
reply(s, &resp)
|
||||
}
|
||||
|
||||
/// Stream a file to the host as it grows, one framed JSON chunk at a time.
|
||||
///
|
||||
/// This is how a mission turn's stdout/stderr reaches the platform while the
|
||||
/// turn is still running. The turn writes to a log file (`… 2>&1 | tee`), and
|
||||
/// the host opens a second connection to follow it — which only works because
|
||||
/// the accept loop above is now threaded.
|
||||
///
|
||||
/// `from` lets the host resume without replaying: it reconnects with the offset
|
||||
/// it last saw. Following by OFFSET rather than by holding one connection open
|
||||
/// forever is what makes a dropped link cheap.
|
||||
///
|
||||
/// Ends when the file stops growing for `idle_ms`, or at `max_secs`. It must
|
||||
/// end: a tail that never returns pins a thread for the life of the VM.
|
||||
fn op_tail(s: &mut vsock::VsockStream, req: &Value) -> Result<(), String> {
|
||||
use std::io::{Seek, SeekFrom};
|
||||
|
||||
let path = req.get("path").and_then(Value::as_str).unwrap_or_default();
|
||||
let mut from = req.get("from").and_then(Value::as_u64).unwrap_or(0);
|
||||
let idle_ms = req.get("idle_ms").and_then(Value::as_u64).unwrap_or(2_000);
|
||||
let max_secs = req.get("max_secs").and_then(Value::as_u64).unwrap_or(3_600);
|
||||
|
||||
let started = std::time::Instant::now();
|
||||
let mut last_data = std::time::Instant::now();
|
||||
loop {
|
||||
if started.elapsed().as_secs() >= max_secs {
|
||||
return reply(s, &json!({ "ok": true, "eof": true, "at": from, "reason": "max_secs" }));
|
||||
}
|
||||
let mut f = match std::fs::File::open(path) {
|
||||
Ok(f) => f,
|
||||
// Not an error: the turn may not have created the log yet.
|
||||
Err(_) => {
|
||||
if last_data.elapsed().as_millis() as u64 >= idle_ms {
|
||||
return reply(s, &json!({ "ok": true, "eof": true, "at": from, "reason": "absent" }));
|
||||
}
|
||||
std::thread::sleep(std::time::Duration::from_millis(200));
|
||||
continue;
|
||||
}
|
||||
};
|
||||
let len = f.metadata().map(|m| m.len()).unwrap_or(0);
|
||||
if len < from {
|
||||
// Truncated or rotated under us. Restart rather than read garbage.
|
||||
from = 0;
|
||||
}
|
||||
if len > from {
|
||||
f.seek(SeekFrom::Start(from))
|
||||
.map_err(|e| format!("seek {path}: {e}"))?;
|
||||
let mut buf = vec![0u8; (len - from).min(MAX_CHUNK) as usize];
|
||||
let n = f.read(&mut buf).map_err(|e| format!("read {path}: {e}"))?;
|
||||
buf.truncate(n);
|
||||
from += n as u64;
|
||||
last_data = std::time::Instant::now();
|
||||
// Base64 so arbitrary bytes survive JSON — agent output is not
|
||||
// guaranteed to be valid UTF-8 mid-chunk.
|
||||
reply(
|
||||
s,
|
||||
&json!({ "ok": true, "eof": false, "at": from, "data": B64.encode(&buf) }),
|
||||
)?;
|
||||
continue;
|
||||
}
|
||||
if last_data.elapsed().as_millis() as u64 >= idle_ms {
|
||||
return reply(s, &json!({ "ok": true, "eof": true, "at": from, "reason": "idle" }));
|
||||
}
|
||||
std::thread::sleep(std::time::Duration::from_millis(200));
|
||||
}
|
||||
}
|
||||
|
||||
/// Largest slice sent in one frame. Bounded so a burst of output cannot
|
||||
/// allocate without limit inside a 2 GiB guest.
|
||||
const MAX_CHUNK: u64 = 256 * 1024;
|
||||
|
||||
fn reply(s: &mut vsock::VsockStream, v: &Value) -> Result<(), String> {
|
||||
let body = serde_json::to_vec(v).map_err(|e| format!("encode reply: {e}"))?;
|
||||
s.write_all(&(body.len() as u32).to_be_bytes())
|
||||
@@ -255,6 +366,9 @@ fn handle(req: &Value) -> Value {
|
||||
"proxy": PROXY_UP.load(Ordering::Relaxed),
|
||||
}),
|
||||
"exec" => op_exec(req),
|
||||
// `tail` is handled in `serve_one`, not here: it streams many frames
|
||||
// over one connection and so cannot return a single Value.
|
||||
"tail" => json!({ "ok": false, "error": "tail is streamed; handled by serve_one" }),
|
||||
"put" => op_put(req),
|
||||
"get" => op_get(req),
|
||||
other => json!({ "ok": false, "error": format!("unknown op: {other}") }),
|
||||
@@ -561,6 +675,20 @@ fn op_get(req: &Value) -> Value {
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
/// The tail loop must terminate. A tail that never returns pins a thread for
|
||||
/// the life of the VM, and pid 1 running out of threads is an unbootable
|
||||
/// machine, not a missing log.
|
||||
#[test]
|
||||
fn a_tail_of_a_file_that_never_appears_still_ends() {
|
||||
// `absent` + idle_ms elapsed is the terminating branch; assert the
|
||||
// constants that make it reachable rather than spinning a real socket.
|
||||
assert!(MAX_CHUNK > 0, "a zero chunk cap would loop without progress");
|
||||
assert!(
|
||||
MAX_CHUNK <= 1024 * 1024,
|
||||
"chunks must stay small enough for a 2 GiB guest"
|
||||
);
|
||||
}
|
||||
|
||||
use super::*;
|
||||
|
||||
/// The CLI reaches the API only by honouring HTTPS_PROXY (measured: with the
|
||||
|
||||
Reference in New Issue
Block a user