Skip to content

Commit c805e00

Browse files
author
Roy Lin
committed
fix(box): container logs show only container output (not runtime internals)
`a3s-box logs` was polluted with runtime boot/exec chatter — guest-init's own INFO tracing (Spawning process, exec/pty server listening, Waiting for container process, ...) plus libkrun's C-init preamble — because the container inherits PID1's serial console and guest-init logged to that same console. Docker `logs` must show ONLY the container process's stdout/stderr. - guest-init: route its OWN tracing to the kernel log (/dev/kmsg) instead of the console, with a <7> debug-priority prefix that stays below the guest kernel's console loglevel (4) so it never echoes back. The fd is opened once before any chroot/pivot and reused (an open fd survives pivot_root), avoiding a mid-boot gap where the new root has no /dev/kmsg. Falls back to stdout if unavailable. with_ansi(false) keeps the kernel log clean. - runtime/log.rs: drop libkrun's `init.krun: ...` preamble (printed before /sbin/init starts) from the json-file and syslog log streams. Verified on KVM: `run -d alpine -- sh -c 'echo HELLO1; echo HELLO2'` then `logs` yields exactly HELLO1/HELLO2 (guestinit=0, krun=0; was ~10 polluting lines). Foreground run + exec + container output unaffected. Bug remaining (separate): --timestamps still shows processing time, needs guest stamp-at-source.
1 parent a00d856 commit c805e00

2 files changed

Lines changed: 104 additions & 1 deletion

File tree

src/guest/init/src/main.rs

Lines changed: 71 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -164,13 +164,83 @@ fn is_tee_environment() -> bool {
164164
a3s_box_core::tee::is_tee_available()
165165
}
166166

167+
/// Raw fd of `/dev/kmsg`, opened ONCE before any chroot/pivot and kept open for
168+
/// the process lifetime. An open file description survives `pivot_root`/`chroot`
169+
/// (it is independent of the path), so reusing this fd avoids the gap where the
170+
/// new root has no `/dev/kmsg` yet — which would otherwise leak a few lines back
171+
/// to the console mid-boot.
172+
static KMSG_FD: std::sync::OnceLock<Option<std::os::unix::io::RawFd>> = std::sync::OnceLock::new();
173+
174+
/// Writer for guest-init's OWN tracing. Routes it to the kernel log
175+
/// (`/dev/kmsg`) instead of the VM console so it never pollutes container logs:
176+
/// the container inherits the console for its stdout/stderr, and Docker-style
177+
/// `logs` must show only that, not runtime internals (init/exec/pty chatter).
178+
/// A `<7>` (debug) priority prefix keeps these lines below the guest kernel's
179+
/// console loglevel (4), so they never echo back to the console. Falls back to
180+
/// stdout when `/dev/kmsg` is unavailable (e.g. non-Linux), preserving the old
181+
/// behavior rather than dropping logs.
182+
enum InitLogWriter {
183+
Kmsg(std::os::unix::io::RawFd),
184+
Stdout(std::io::Stdout),
185+
}
186+
187+
impl std::io::Write for InitLogWriter {
188+
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
189+
match self {
190+
InitLogWriter::Kmsg(fd) => {
191+
// /dev/kmsg treats each write() as one record: prefix the
192+
// priority and flatten embedded newlines so a formatted event
193+
// stays a single kernel-log record.
194+
let mut record = Vec::with_capacity(buf.len() + 13);
195+
record.extend_from_slice(b"<7>a3s-init: ");
196+
record.extend(buf.iter().map(|&b| if b == b'\n' { b' ' } else { b }));
197+
// SAFETY: *fd is a valid, process-lifetime fd to /dev/kmsg; a
198+
// failed write is intentionally ignored (logging must never panic).
199+
unsafe {
200+
libc::write(*fd, record.as_ptr() as *const libc::c_void, record.len());
201+
}
202+
Ok(buf.len())
203+
}
204+
InitLogWriter::Stdout(out) => out.write(buf),
205+
}
206+
}
207+
208+
fn flush(&mut self) -> std::io::Result<()> {
209+
match self {
210+
InitLogWriter::Kmsg(_) => Ok(()),
211+
InitLogWriter::Stdout(out) => out.flush(),
212+
}
213+
}
214+
}
215+
216+
fn make_init_log_writer() -> InitLogWriter {
217+
match KMSG_FD.get().copied().flatten() {
218+
Some(fd) => InitLogWriter::Kmsg(fd),
219+
None => InitLogWriter::Stdout(std::io::stdout()),
220+
}
221+
}
222+
167223
fn main() {
168-
// Initialize logging
224+
// Open /dev/kmsg once (before any chroot) and keep it open for the whole
225+
// process via into_raw_fd, so guest-init's logs reach the kernel log
226+
// reliably across the pivot. Container logs stay clean (see InitLogWriter).
227+
use std::os::unix::io::IntoRawFd;
228+
let kmsg_fd = std::fs::OpenOptions::new()
229+
.write(true)
230+
.open("/dev/kmsg")
231+
.ok()
232+
.map(|file| file.into_raw_fd());
233+
let _ = KMSG_FD.set(kmsg_fd);
234+
235+
// Initialize logging. guest-init's own logs go to the kernel log, NOT the
236+
// console, to keep container logs clean.
169237
tracing_subscriber::fmt()
170238
.with_env_filter(
171239
tracing_subscriber::EnvFilter::try_from_default_env()
172240
.unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")),
173241
)
242+
.with_ansi(false)
243+
.with_writer(make_init_log_writer)
174244
.init();
175245

176246
info!("a3s-box guest init starting (PID {})", process::id());

src/runtime/src/log.rs

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,15 @@ pub fn json_log_path(log_dir: &Path) -> PathBuf {
3939
log_dir.join("container.json")
4040
}
4141

42+
/// True for console lines that are VM/runtime boot internals, not container
43+
/// output. Currently libkrun's C-init preamble (`init.krun: ...`), emitted to
44+
/// the console before `/sbin/init` (guest-init) takes over. guest-init's own
45+
/// tracing is routed to `/dev/kmsg` and never reaches the console, so this is
46+
/// the only remaining non-container source on it.
47+
fn is_runtime_console_noise(line: &str) -> bool {
48+
line.starts_with("init.krun:")
49+
}
50+
4251
/// Tail console.log and write Docker-compatible JSON lines to container.json.
4352
fn run_json_file_processor(console_log: &Path, log_dir: &Path, max_size: u64, max_file: u32) {
4453
// Wait for console.log to appear
@@ -71,6 +80,14 @@ fn run_json_file_processor(console_log: &Path, log_dir: &Path, max_size: u64, ma
7180
}
7281
};
7382

83+
// Drop libkrun's C-init boot preamble (`init.krun: ...`) printed to the
84+
// console before /sbin/init starts. It is runtime internals, not
85+
// container output — Docker `logs` must show only the latter. (guest-init's
86+
// own tracing already goes to /dev/kmsg, not the console.)
87+
if is_runtime_console_noise(&line) {
88+
continue;
89+
}
90+
7491
let entry = LogEntry {
7592
log: format!("{}\n", line),
7693
stream: "stdout".to_string(),
@@ -128,6 +145,9 @@ fn run_syslog_processor(console_log: &Path, address: &str, _facility: &str, tag:
128145
continue;
129146
}
130147
};
148+
if is_runtime_console_noise(&line) {
149+
continue;
150+
}
131151
// RFC 3164 format: <priority>tag: message
132152
// facility=daemon(3), severity=info(6) → priority = 3*8+6 = 30
133153
let msg = format!("<30>{}: {}", tag, line);
@@ -148,6 +168,9 @@ fn run_syslog_processor(console_log: &Path, address: &str, _facility: &str, tag:
148168
continue;
149169
}
150170
};
171+
if is_runtime_console_noise(&line) {
172+
continue;
173+
}
151174
let msg = format!("<30>{}: {}\n", tag, line);
152175
if stream.write_all(msg.as_bytes()).is_err() {
153176
// Connection lost — try to reconnect once
@@ -265,6 +288,16 @@ mod tests {
265288
use std::io::Read;
266289
use tempfile::TempDir;
267290

291+
#[test]
292+
fn test_is_runtime_console_noise() {
293+
assert!(is_runtime_console_noise("init.krun: mount_filesystems ok"));
294+
assert!(is_runtime_console_noise("init.krun: execvp(/sbin/init) starting"));
295+
// Real container output must pass through, even if it mentions krun.
296+
assert!(!is_runtime_console_noise("L1"));
297+
assert!(!is_runtime_console_noise("starting app (init.krun: ignored)"));
298+
assert!(!is_runtime_console_noise(""));
299+
}
300+
268301
#[test]
269302
fn test_rotating_writer_basic() {
270303
let dir = TempDir::new().unwrap();

0 commit comments

Comments
 (0)