Skip to content

Commit 66fabe5

Browse files
author
Roy Lin
committed
feat(box): tag container logs stdout vs stderr (split virtio-console)
container.json hard-coded stream="stdout" for every line — a container's stderr (`echo x 1>&2`) was mislabeled stdout, the last Docker json-file divergence. (The pipe-capture approach to separate streams was adversarially rejected — it can freeze the container / hang shutdown.) Use libkrun's 3-fd virtio-console instead: guest stdout -> console.log, stderr -> console.err.log (krun_add_virtio_console_default, after krun_disable_implicit_console). EMPIRICALLY verified libkrun separates the streams with NO guest change and no pipe (console devices aren't bounded pipes the container can block on, so no freeze/deadlock). - shim: split console by default (BOX_NO_SPLIT_STDERR forces legacy merged; falls back to merged if the err file can't be opened). - core/log.rs: the processor tails BOTH files on scoped threads sharing one RotatingWriter, tagging each line's stream; filters libkrun's `init.krun:` preamble on BOTH streams (it can land on either). - cli: foreground `run` and `attach` tail console.err.log to the terminal's stderr (stdout->fd1, stderr->fd2, like Docker); `logs` routes stderr lines to its stderr. KVM-verified: `echo OUT; echo ERR 1>&2` -> container.json tags OUT=stdout, ERR=stderr, zero init.krun noise; foreground shows stdout on fd1 + stderr on fd2; detached logs still complete; exit code 5 propagates. Completes Docker json-file log parity.
1 parent f728537 commit 66fabe5

7 files changed

Lines changed: 165 additions & 52 deletions

File tree

src/cli/src/commands/attach.rs

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,12 @@ pub async fn execute(args: AttachArgs) -> Result<(), Box<dyn std::error::Error>>
5353

5454
println!("Attached to box {}. Press Ctrl-C to detach.", record.name);
5555

56+
let console_err = console_log.with_file_name("console.err.log");
5657
let log_handle = tokio::spawn(async move {
57-
super::tail_file(&console_log).await;
58+
tokio::join!(
59+
super::tail_file(&console_log),
60+
super::tail_file_stream(&console_err, true),
61+
);
5862
});
5963

6064
let _ = tokio::signal::ctrl_c().await;

src/cli/src/commands/logs.rs

Lines changed: 11 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -241,11 +241,18 @@ fn print_json_line(
241241
}
242242
}
243243

244-
// The log field already contains the trailing newline
245-
if timestamps {
246-
print!("{} {}", entry.time, entry.log);
244+
// The log field already contains the trailing newline. Route stderr lines to
245+
// the terminal's stderr, like Docker `logs`.
246+
let line = if timestamps {
247+
format!("{} {}", entry.time, entry.log)
248+
} else {
249+
entry.log.clone()
250+
};
251+
if entry.stream == "stderr" {
252+
use std::io::Write as _;
253+
let _ = std::io::stderr().write_all(line.as_bytes());
247254
} else {
248-
print!("{}", entry.log);
255+
print!("{line}");
249256
}
250257
}
251258

src/cli/src/commands/mod.rs

Lines changed: 15 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -241,6 +241,14 @@ pub(crate) fn resolve_box_rootfs(box_dir: &std::path::Path) -> Option<PathBuf> {
241241
/// Waits for the file to exist, then continuously reads and prints new data.
242242
/// Used by `run` (foreground mode) and `attach`.
243243
pub(crate) async fn tail_file(path: &std::path::Path) {
244+
tail_file_stream(path, false).await;
245+
}
246+
247+
/// Tail a console file to the terminal. `to_stderr` routes it to the terminal's
248+
/// stderr — used for the container's stderr console (console.err.log) so a
249+
/// foreground `run`/`attach` shows stdout and stderr like Docker.
250+
pub(crate) async fn tail_file_stream(path: &std::path::Path, to_stderr: bool) {
251+
use std::io::Write as _;
244252
use tokio::io::AsyncReadExt;
245253

246254
// Wait for file to exist
@@ -264,7 +272,13 @@ pub(crate) async fn tail_file(path: &std::path::Path) {
264272
}
265273
Ok(n) => {
266274
let text = String::from_utf8_lossy(&buf[..n]);
267-
print!("{text}");
275+
if to_stderr {
276+
let mut err = std::io::stderr();
277+
let _ = err.write_all(text.as_bytes());
278+
let _ = err.flush();
279+
} else {
280+
print!("{text}");
281+
}
268282
}
269283
Err(_) => break,
270284
}

src/cli/src/commands/run.rs

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -624,8 +624,14 @@ async fn run_foreground(
624624
);
625625

626626
let console_log = ctx.box_dir.join("logs").join("console.log");
627+
let console_err = ctx.box_dir.join("logs").join("console.err.log");
627628
let log_handle = tokio::spawn(async move {
628-
super::tail_file(&console_log).await;
629+
// Stream the container's stdout (console.log) and stderr
630+
// (console.err.log, split console) to the terminal's stdout/stderr.
631+
tokio::join!(
632+
super::tail_file(&console_log),
633+
super::tail_file_stream(&console_err, true),
634+
);
629635
});
630636

631637
let name = ctx.name.clone();

src/core/src/log.rs

Lines changed: 75 additions & 42 deletions
Original file line numberDiff line numberDiff line change
@@ -242,41 +242,75 @@ fn open_console(console_log: &Path, stop: &AtomicBool) -> Option<std::fs::File>
242242
}
243243

244244
/// Tail console.log and write one Docker-style JSON record per container line.
245+
/// The stderr companion to `console.log` (libkrun's 3-fd console sends guest
246+
/// stderr here, stdout to `console.log`).
247+
pub fn stderr_console_path(console_log: &Path) -> PathBuf {
248+
console_log.with_file_name("console.err.log")
249+
}
250+
251+
/// Tail one console file, emitting each container line via `emit(line, stream)`.
252+
/// `filter_noise` drops libkrun's `init.krun:` preamble (only on the stdout
253+
/// console). Blocks until `stop` is set and the file is drained.
254+
fn run_tagged_tail(
255+
file: &Path,
256+
stream: &str,
257+
filter_noise: bool,
258+
stop: &AtomicBool,
259+
emit: &(dyn Fn(&str, &str) + Sync),
260+
) {
261+
let f = match open_console(file, stop) {
262+
Some(f) => f,
263+
None => return,
264+
};
265+
let mut reader = BufReader::new(f);
266+
let mut buf = String::new();
267+
while let Some(line) = tail_next_line(&mut reader, &mut buf, stop) {
268+
if filter_noise && is_runtime_console_noise(&line) {
269+
continue;
270+
}
271+
emit(&line, stream);
272+
}
273+
}
274+
245275
fn run_json_file_processor(
246276
console_log: &Path,
247277
log_dir: &Path,
248278
max_size: u64,
249279
max_file: u32,
250280
stop: &AtomicBool,
251281
) {
252-
let file = match open_console(console_log, stop) {
253-
Some(f) => f,
254-
None => return,
255-
};
256-
let mut reader = BufReader::new(file);
257282
let json_path = json_log_path(log_dir);
258-
let mut writer = match RotatingWriter::new(&json_path, max_size, max_file) {
283+
let writer = std::sync::Mutex::new(match RotatingWriter::new(&json_path, max_size, max_file) {
259284
Ok(w) => w,
260285
Err(_) => return,
261-
};
286+
});
287+
let err_log = stderr_console_path(console_log);
262288

263-
let mut buf = String::new();
264-
while let Some(line) = tail_next_line(&mut reader, &mut buf, stop) {
265-
if is_runtime_console_noise(&line) {
266-
continue;
267-
}
289+
// Write one tagged JSON record per line; shared by the stdout and stderr
290+
// tail threads (the Mutex serializes their interleave into container.json).
291+
let emit = |line: &str, stream: &str| {
268292
let entry = LogEntry {
269293
log: format!("{line}\n"),
270-
stream: "stdout".to_string(),
294+
stream: stream.to_string(),
271295
time: chrono::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Nanos, true),
272296
};
273297
if let Ok(json) = serde_json::to_string(&entry) {
274-
let _ = writer.write_line(&json);
298+
if let Ok(mut w) = writer.lock() {
299+
let _ = w.write_line(&json);
300+
}
275301
}
276-
}
302+
};
303+
let emit: &(dyn Fn(&str, &str) + Sync) = &emit;
304+
305+
std::thread::scope(|s| {
306+
s.spawn(|| run_tagged_tail(console_log, "stdout", true, stop, emit));
307+
// libkrun's `init.krun:` preamble can land on EITHER stream, so filter
308+
// the noise on stderr too.
309+
s.spawn(|| run_tagged_tail(&err_log, "stderr", true, stop, emit));
310+
});
277311
}
278312

279-
/// Forward console.log lines to a syslog endpoint via UDP or TCP.
313+
/// Forward both console streams (stdout + stderr) to a syslog endpoint.
280314
fn run_syslog_processor(
281315
console_log: &Path,
282316
address: &str,
@@ -286,54 +320,53 @@ fn run_syslog_processor(
286320
) {
287321
use std::net::UdpSocket;
288322

289-
let file = match open_console(console_log, stop) {
290-
Some(f) => f,
291-
None => return,
292-
};
293323
let (proto, addr) = if let Some(rest) = address.strip_prefix("udp://") {
294324
("udp", rest)
295325
} else if let Some(rest) = address.strip_prefix("tcp://") {
296326
("tcp", rest)
297327
} else {
298328
("udp", address)
299329
};
300-
301-
let mut reader = BufReader::new(file);
302-
let mut buf = String::new();
330+
let err_log = stderr_console_path(console_log);
303331

304332
match proto {
305333
"udp" => {
306334
let socket = match UdpSocket::bind("0.0.0.0:0") {
307335
Ok(s) => s,
308336
Err(_) => return,
309337
};
310-
while let Some(line) = tail_next_line(&mut reader, &mut buf, stop) {
311-
if is_runtime_console_noise(&line) {
312-
continue;
313-
}
314-
// RFC 3164: <priority>tag: message; daemon(3)*8 + info(6) = 30.
338+
// RFC 3164: <priority>tag: message; daemon(3)*8 + info(6) = 30.
339+
let emit = |line: &str, _stream: &str| {
315340
let msg = format!("<30>{tag}: {line}");
316341
let _ = socket.send_to(msg.as_bytes(), addr);
317-
}
342+
};
343+
let emit: &(dyn Fn(&str, &str) + Sync) = &emit;
344+
std::thread::scope(|s| {
345+
s.spawn(|| run_tagged_tail(console_log, "stdout", true, stop, emit));
346+
s.spawn(|| run_tagged_tail(&err_log, "stderr", true, stop, emit));
347+
});
318348
}
319349
"tcp" => {
320-
let mut stream = match std::net::TcpStream::connect(addr) {
321-
Ok(s) => s,
350+
let stream = match std::net::TcpStream::connect(addr) {
351+
Ok(s) => std::sync::Mutex::new(s),
322352
Err(_) => return,
323353
};
324-
while let Some(line) = tail_next_line(&mut reader, &mut buf, stop) {
325-
if is_runtime_console_noise(&line) {
326-
continue;
327-
}
354+
let emit = |line: &str, _stream: &str| {
328355
let msg = format!("<30>{tag}: {line}\n");
329-
if stream.write_all(msg.as_bytes()).is_err() {
330-
stream = match std::net::TcpStream::connect(addr) {
331-
Ok(s) => s,
332-
Err(_) => return,
333-
};
334-
let _ = stream.write_all(msg.as_bytes());
356+
if let Ok(mut s) = stream.lock() {
357+
if s.write_all(msg.as_bytes()).is_err() {
358+
if let Ok(news) = std::net::TcpStream::connect(addr) {
359+
*s = news;
360+
let _ = s.write_all(msg.as_bytes());
361+
}
362+
}
335363
}
336-
}
364+
};
365+
let emit: &(dyn Fn(&str, &str) + Sync) = &emit;
366+
std::thread::scope(|sc| {
367+
sc.spawn(|| run_tagged_tail(console_log, "stdout", true, stop, emit));
368+
sc.spawn(|| run_tagged_tail(&err_log, "stderr", true, stop, emit));
369+
});
337370
}
338371
_ => {}
339372
}

src/shim/src/krun/context.rs

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,7 +21,8 @@ use libkrun_sys::{krun_add_net_tcp, krun_add_vsock_port_windows, krun_set_kernel
2121
#[cfg(target_os = "linux")]
2222
use libkrun_sys::{krun_add_net_unixstream, krun_split_irqchip};
2323
use libkrun_sys::{
24-
krun_add_virtiofs, krun_create_ctx, krun_free_ctx, krun_init_log, krun_set_console_output,
24+
krun_add_virtio_console_default, krun_add_virtiofs, krun_create_ctx,
25+
krun_disable_implicit_console, krun_free_ctx, krun_init_log, krun_set_console_output,
2526
krun_set_env, krun_set_exec, krun_set_rlimits, krun_set_root, krun_set_vm_config,
2627
krun_set_workdir, krun_setgid, krun_setuid, krun_start_enter,
2728
};
@@ -437,6 +438,25 @@ impl KrunContext {
437438
)
438439
}
439440

441+
/// Replace the implicit console with a virtio-console whose stdout and
442+
/// stderr go to SEPARATE host fds (so the guest's stderr can be tagged).
443+
/// `input_fd` may be -1 (no stdin). Caller owns the fds for the VM lifetime.
444+
pub unsafe fn add_split_console(
445+
&self,
446+
input_fd: i32,
447+
output_fd: i32,
448+
err_fd: i32,
449+
) -> Result<()> {
450+
check_status(
451+
"krun_disable_implicit_console",
452+
krun_disable_implicit_console(self.ctx_id),
453+
)?;
454+
check_status(
455+
"krun_add_virtio_console_default",
456+
krun_add_virtio_console_default(self.ctx_id, input_fd, output_fd, err_fd),
457+
)
458+
}
459+
440460
/// Enable split IRQ chip mode (required for TEE VMs).
441461
///
442462
/// This must be called before starting a TEE-enabled VM.

src/shim/src/main.rs

Lines changed: 31 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -756,8 +756,37 @@ unsafe fn configure_and_start_vm(spec: &InstanceSpec) -> Result<()> {
756756
message: format!("Invalid console output path: {}", console_path.display()),
757757
hint: None,
758758
})?;
759-
tracing::debug!(console_path = console_str, "Redirecting console output");
760-
ctx.set_console_output(console_str)?;
759+
// Split console: guest stdout -> console.log, stderr -> console.err.log
760+
// (libkrun's 3-fd virtio-console separates the streams), so the log
761+
// processor can tag each line's stream like Docker's json-file driver.
762+
// Falls back to the merged single-file console if the err file can't be
763+
// opened. BOX_NO_SPLIT_STDERR forces the legacy merged behavior.
764+
use std::os::unix::io::AsRawFd;
765+
let opened = if std::env::var_os("BOX_NO_SPLIT_STDERR").is_none() {
766+
let err_path = console_path.with_file_name("console.err.log");
767+
let open = |p: &std::path::Path| {
768+
std::fs::OpenOptions::new().create(true).append(true).open(p)
769+
};
770+
match (open(console_path), open(&err_path)) {
771+
(Ok(out_f), Ok(err_f)) => Some((out_f, err_f)),
772+
_ => None,
773+
}
774+
} else {
775+
None
776+
};
777+
match opened {
778+
Some((out_f, err_f)) => {
779+
ctx.add_split_console(-1, out_f.as_raw_fd(), err_f.as_raw_fd())?;
780+
// Keep the fds open for the VM's lifetime.
781+
std::mem::forget(out_f);
782+
std::mem::forget(err_f);
783+
tracing::debug!("split console enabled (stdout/stderr separated)");
784+
}
785+
None => {
786+
tracing::debug!(console_path = console_str, "Redirecting console output (merged)");
787+
ctx.set_console_output(console_str)?;
788+
}
789+
}
761790
}
762791

763792
// Configure TEE if specified (only available on Linux with SEV support)

0 commit comments

Comments
 (0)