From 0bb870cf4d0bb6189ea3e298f2fb81f95b21da55 Mon Sep 17 00:00:00 2001 From: Nir Soffer Date: Tue, 24 Feb 2026 23:59:18 +0200 Subject: [PATCH 1/4] libkrun: use microsecond timestamps in debug logs The default second-resolution timestamps make it impossible to understand the timing of events. Use format_timestamp_micros() in both logger init paths (krun_set_log_level and krun_init_log) so log output shows microsecond precision. Assisted-by: Cursor/Claude Opus 4.6 Signed-off-by: Nir Soffer --- src/libkrun/src/lib.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/libkrun/src/lib.rs b/src/libkrun/src/lib.rs index 5426bafbb..ceae52c80 100644 --- a/src/libkrun/src/lib.rs +++ b/src/libkrun/src/lib.rs @@ -444,7 +444,9 @@ fn log_level_to_filter_str(level: u32) -> &'static str { #[no_mangle] pub extern "C" fn krun_set_log_level(level: u32) -> i32 { let filter = log_level_to_filter_str(level); - env_logger::Builder::from_env(Env::default().default_filter_or(filter)).init(); + env_logger::Builder::from_env(Env::default().default_filter_or(filter)) + .format_timestamp_micros() + .init(); #[cfg(feature = "aws-nitro")] { @@ -504,7 +506,7 @@ pub unsafe extern "C" fn krun_init_log(target: RawFd, level: u32, style: u32, op builder.parse_filters(filter).parse_write_style(write_style); builder }; - builder.target(target).init(); + builder.format_timestamp_micros().target(target).init(); KRUN_SUCCESS } From 5cbf82f39e41609752a3b246d23eb0ebb2339aaf Mon Sep 17 00:00:00 2001 From: Nir Soffer Date: Thu, 26 Feb 2026 15:03:09 +0200 Subject: [PATCH 2/4] utils/macos/epoll: Return early on errors Make the code more clear, easier to follow by handling error from kevent() early. Assisted-by: Cursor/Claude Opus 4.6 Signed-off-by: Nir Soffer --- src/utils/src/macos/epoll.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/utils/src/macos/epoll.rs b/src/utils/src/macos/epoll.rs index f6141cd53..7346b3920 100644 --- a/src/utils/src/macos/epoll.rs +++ b/src/utils/src/macos/epoll.rs @@ -263,6 +263,10 @@ impl Epoll { debug!("ret: {ret}"); + if ret < 0 { + return Err(io::Error::last_os_error()); + } + for i in 0..ret { debug!("kev: {:?}", kevs[i as usize]); if kevs[i as usize].0.filter == libc::EVFILT_READ { @@ -280,11 +284,7 @@ impl Epoll { events[i as usize].u64 = kevs[i as usize].udata(); } - match ret { - -1 => Err(io::Error::last_os_error()), - 0 => Ok(0), - nev => Ok(nev as usize), - } + Ok(ret as usize) } } From ee306d78a3fb181a907682aec63ce8ed5115b3fb Mon Sep 17 00:00:00 2001 From: Nir Soffer Date: Thu, 26 Feb 2026 17:04:12 +0200 Subject: [PATCH 3/4] utils/macos/epoll: cast kevent count to usize before the loop The repeated `i as usize` casts on every array access made the loop harder to read. Assisted-by: Cursor/Claude Opus 4.6 Signed-off-by: Nir Soffer --- src/utils/src/macos/epoll.rs | 22 ++++++++++++---------- 1 file changed, 12 insertions(+), 10 deletions(-) diff --git a/src/utils/src/macos/epoll.rs b/src/utils/src/macos/epoll.rs index 7346b3920..f1fe7e4ad 100644 --- a/src/utils/src/macos/epoll.rs +++ b/src/utils/src/macos/epoll.rs @@ -267,24 +267,26 @@ impl Epoll { return Err(io::Error::last_os_error()); } - for i in 0..ret { - debug!("kev: {:?}", kevs[i as usize]); - if kevs[i as usize].0.filter == libc::EVFILT_READ { - events[i as usize].events = EventSet::IN.bits(); - } else if kevs[i as usize].0.filter == libc::EVFILT_WRITE { - events[i as usize].events = EventSet::OUT.bits(); + let nevents = ret as usize; + + for i in 0..nevents { + debug!("kev: {:?}", kevs[i]); + if kevs[i].0.filter == libc::EVFILT_READ { + events[i].events = EventSet::IN.bits(); + } else if kevs[i].0.filter == libc::EVFILT_WRITE { + events[i].events = EventSet::OUT.bits(); } - if kevs[i as usize].0.flags & libc::EV_EOF != 0 { - events[i as usize].events |= if kevs[i as usize].0.flags & libc::EV_CLEAR != 0 { + if kevs[i].0.flags & libc::EV_EOF != 0 { + events[i].events |= if kevs[i].0.flags & libc::EV_CLEAR != 0 { EventSet::READ_HANG_UP.bits() } else { EventSet::HANG_UP.bits() }; } - events[i as usize].u64 = kevs[i as usize].udata(); + events[i].u64 = kevs[i].udata(); } - Ok(ret as usize) + Ok(nevents) } } From 99adc35c6b36b01147dbf249c78e6b7ffc924331 Mon Sep 17 00:00:00 2001 From: Nir Soffer Date: Thu, 26 Feb 2026 17:24:29 +0200 Subject: [PATCH 4/4] utils/macos/epoll: Improve kevent debug log Previously we logged the raw event before processing it. Now we process the event and log a more clear and easier to understand message. With this can tell if we woke up for READ or WRITE event and we the log make the values more clear. Example logs: [2026-02-26T18:28:23.856913Z DEBUG utils::macos::epoll] kevent: WRITE fd=3 data=66560 [2026-02-26T18:28:23.856923Z DEBUG utils::macos::epoll] kevent: READ fd=3 data=3539700 [2026-02-26T18:28:23.859383Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=8 Assisted-by: Cursor/Claude Opus 4.6 Signed-off-by: Nir Soffer --- src/utils/src/macos/epoll.rs | 20 +++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) diff --git a/src/utils/src/macos/epoll.rs b/src/utils/src/macos/epoll.rs index f1fe7e4ad..b694f697f 100644 --- a/src/utils/src/macos/epoll.rs +++ b/src/utils/src/macos/epoll.rs @@ -12,6 +12,18 @@ use std::time::Duration; use bitflags::bitflags; use log::debug; +fn event_name(event: u32) -> &'static str { + match event { + e if e == EventSet::IN.bits() => "READ", + e if e == EventSet::OUT.bits() => "WRITE", + e if e == (EventSet::IN | EventSet::READ_HANG_UP).bits() => "READ_EOF", + e if e == (EventSet::IN | EventSet::HANG_UP).bits() => "EOF", + e if e == EventSet::HANG_UP.bits() => "HANG_UP", + e if e == EventSet::READ_HANG_UP.bits() => "READ_HANG_UP", + _ => "UNKNOWN", + } +} + #[repr(i32)] pub enum ControlOperation { Add, @@ -270,7 +282,6 @@ impl Epoll { let nevents = ret as usize; for i in 0..nevents { - debug!("kev: {:?}", kevs[i]); if kevs[i].0.filter == libc::EVFILT_READ { events[i].events = EventSet::IN.bits(); } else if kevs[i].0.filter == libc::EVFILT_WRITE { @@ -284,6 +295,13 @@ impl Epoll { }; } events[i].u64 = kevs[i].udata(); + + let fd = kevs[i].0.ident; + let data = kevs[i].0.data; + debug!( + "kevent: {} fd={fd} data={data}", + event_name(events[i].events) + ); } Ok(nevents)