diff --git a/src/io/lib.rs b/src/io/lib.rs index 82b8e55ea107..ffb3476f3835 100644 --- a/src/io/lib.rs +++ b/src/io/lib.rs @@ -2234,6 +2234,14 @@ pub mod closer { pub struct Closer { pub(crate) fd: Fd, task: WorkPoolTask, + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + scheduled_from: bun_core::StoredTrace, + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + scheduled_on_tid: i64, + /// What the fd pointed at when the close was scheduled (empty if it + /// was already closed by then). + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + scheduled_description: bun_sys::close_ledger::FdDescription, } #[cfg(not(windows))] @@ -2243,6 +2251,39 @@ pub mod closer { unsafe impl bun_threading::work_pool::OwnedTask for Closer { fn run(self: Box) { use bun_sys::FdExt; + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + { + #[allow(clippy::print_stderr)] + if let Some(err) = self.fd.close_allowing_bad_file_descriptor(None) { + if err.errno == bun_sys::E::EBADF as _ { + std::eprintln!( + "\n==================== Closer: close({}) = EBADF ====================", + self.fd.native() + ); + std::eprintln!( + "when this Closer was scheduled the fd was \"{}\" (empty = already closed at that point)", + self.scheduled_description.as_str() + ); + std::eprintln!( + "this Closer was scheduled on tid {} at:", + self.scheduled_on_tid + ); + bun_core::dump_stack_trace( + &self.scheduled_from.trace(), + bun_core::DumpStackTraceOptions::default(), + ); + std::eprintln!( + "======================================================================\n" + ); + panic!( + "Closer: fd {} was already closed when the async close ran (see report above)", + self.fd.native() + ); + } + } + return; + } + #[allow(unreachable_code)] self.fd.close(); } } @@ -2258,6 +2299,12 @@ pub mod closer { node: Default::default(), callback: ::__callback, }, + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + scheduled_from: bun_core::StoredTrace::capture(None), + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + scheduled_on_tid: bun_sys::close_ledger::current_tid(), + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + scheduled_description: bun_sys::close_ledger::FdDescription::of(fd.native()), })); } } diff --git a/src/io/pipes.rs b/src/io/pipes.rs index 9aab1226ab09..0dbb30c473ca 100644 --- a/src/io/pipes.rs +++ b/src/io/pipes.rs @@ -62,6 +62,18 @@ impl PollOrFd { #[cfg(windows)] let _ = close_fd; let fd = self.get_fd(); + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + if fd != Fd::INVALID { + bun_sys::close_ledger::record_registration_event( + match (self.tag_name(), close_fd) { + ("poll", true) => "close_impl(poll, close_fd)", + ("poll", false) => "close_impl(poll, keep fd)", + (_, true) => "close_impl(bare fd, close_fd)", + (_, false) => "close_impl(bare fd, keep fd)", + }, + fd.native(), + ); + } #[cfg(target_os = "macos")] let mut close_async = true; #[cfg(all(not(target_os = "macos"), not(windows)))] diff --git a/src/io/posix_event_loop.rs b/src/io/posix_event_loop.rs index cf509017697d..e206ab4ae24c 100644 --- a/src/io/posix_event_loop.rs +++ b/src/io/posix_event_loop.rs @@ -667,9 +667,37 @@ impl FilePoll { let ctl = unsafe { linux::epoll_ctl(watcher_fd, op, fd.native(), &raw mut event) }; self.flags.insert(Flags::WasEverRegistered); if let Some(errno) = errno_sys(ctl, sys::Tag::epoll_ctl) { + #[cfg(debug_assertions)] + { + let what = std::format!( + "epoll_ctl({}, fd {}, {}) failed: {} (poll flags before: {})", + if op == EPOLL::CTL_MOD { + "CTL_MOD" + } else { + "CTL_ADD" + }, + fd.native(), + <&'static str>::from(flag), + errno + .as_ref() + .err() + .and_then(|e| core::str::from_utf8(e.name()).ok()) + .unwrap_or("?"), + FlagsFormatter(self.flags), + ); + sys::close_ledger::report_fd_event(&what, fd.native()); + } self.deactivate(loop_); return errno; } + #[cfg(debug_assertions)] + { + // Only ADDs create kernel registrations; MODs are noise here. + if op == EPOLL::CTL_ADD { + let what = std::format!("ADD ok ({})", <&'static str>::from(flag)); + sys::close_ledger::record_registration_event(&what, fd.native()); + } + } } #[cfg(target_os = "macos")] { @@ -923,6 +951,15 @@ impl FilePoll { || self.flags.contains(Flags::PollMachport) || self.flags.contains(Flags::PollMemoryPressure)) { + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + sys::close_ledger::record_registration_event( + if force_unregister { + "DEL skipped(force): no poll flags" + } else { + "DEL skipped: no poll flags" + }, + fd.native(), + ); // no-op return sys::Result::Ok(()); } @@ -961,6 +998,8 @@ impl FilePoll { self.flags.remove(Flags::PollWritable); self.flags.remove(Flags::PollMachport); self.flags.remove(Flags::PollMemoryPressure); + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + sys::close_ledger::record_registration_event("DEL skipped: needs_rearm", fd.native()); return sys::Result::Ok(()); } @@ -983,9 +1022,29 @@ impl FilePoll { }; match sys::get_errno(ctl) { - sys::E::SUCCESS => {} - e if deregistration_already_gone(e) => {} - e => return sys::Result::Err(sys::Error::from_code(e, sys::Tag::epoll_ctl)), + sys::E::SUCCESS => { + #[cfg(debug_assertions)] + sys::close_ledger::record_registration_event("DEL ok", fd.native()); + } + e if deregistration_already_gone(e) => { + #[cfg(debug_assertions)] + sys::close_ledger::record_registration_event( + if e == sys::E::EBADF { + "DEL -> EBADF (fd already closed)" + } else { + "DEL -> ENOENT (not registered)" + }, + fd.native(), + ); + } + e => { + #[cfg(debug_assertions)] + sys::close_ledger::record_registration_event( + "DEL failed (other errno)", + fd.native(), + ); + return sys::Result::Err(sys::Error::from_code(e, sys::Tag::epoll_ctl)); + } } } #[cfg(target_os = "macos")] diff --git a/src/sys/close_ledger.rs b/src/sys/close_ledger.rs new file mode 100644 index 000000000000..ec5cb5df2958 --- /dev/null +++ b/src/sys/close_ledger.rs @@ -0,0 +1,248 @@ +//! Debug-only (`debug_assertions`) diagnostics for double closes. +//! +//! Every successful `close(2)` issued through `bun_sys` records the calling +//! thread, what the descriptor pointed at (`/proc/self/fd/N`), and a +//! frame-pointer stack trace, keyed by fd number (the last few closes of each +//! number are kept). When a later close of the same number fails with `EBADF` +//! (a use-after-close, or a second owner closing a descriptor it does not +//! own), the reporter prints that history. Traces are printed as raw return +//! addresses (symbolize them against the binary with llvm-symbolizer). +#![allow(clippy::print_stderr)] + +use std::sync::Mutex; +use std::sync::atomic::{AtomicU64, Ordering}; + +use bun_core::{DumpStackTraceOptions, StoredTrace}; + +/// `readlink("/proc/self/fd/N")`, truncated to a fixed buffer. +#[derive(Clone, Copy)] +pub struct FdDescription { + len: u8, + bytes: [u8; 63], +} + +impl FdDescription { + pub const UNKNOWN: FdDescription = FdDescription { + len: 0, + bytes: [0; 63], + }; + + /// Describe a currently-open descriptor. Call this *before* closing it. + pub fn of(fd: i32) -> FdDescription { + let mut out = FdDescription::UNKNOWN; + if fd < 0 { + return out; + } + let path = format!("/proc/self/fd/{fd}\0"); + // SAFETY: `path` is NUL-terminated; `bytes` is valid for `bytes.len()` writes. + let n = unsafe { + libc::readlink( + path.as_ptr().cast(), + out.bytes.as_mut_ptr().cast(), + out.bytes.len(), + ) + }; + if n > 0 { + out.len = n as u8; + } + out + } + + pub fn as_str(&self) -> &str { + core::str::from_utf8(&self.bytes[..self.len as usize]).unwrap_or("") + } +} + +#[derive(Clone, Copy)] +struct Slot { + /// 0 = never recorded. + seq: u64, + tid: i64, + description: FdDescription, + trace: StoredTrace, +} + +impl Slot { + const EMPTY: Slot = Slot { + seq: 0, + tid: 0, + description: FdDescription::UNKNOWN, + trace: StoredTrace::EMPTY, + }; +} + +const MAX_TRACKED_FD: usize = 4096; +const HISTORY: usize = 3; + +static LEDGER: Mutex<[[Slot; HISTORY]; MAX_TRACKED_FD]> = + Mutex::new([[Slot::EMPTY; HISTORY]; MAX_TRACKED_FD]); +static SEQ: AtomicU64 = AtomicU64::new(1); + +pub fn current_tid() -> i64 { + // SAFETY: SYS_gettid takes no arguments and cannot fail. + unsafe { libc::syscall(libc::SYS_gettid) as i64 } +} + +/// Record that `fd` (which pointed at `description` before the call) was just +/// closed successfully by the current thread. +pub fn record_closed(fd: i32, description: FdDescription) { + if fd < 0 || fd as usize >= MAX_TRACKED_FD { + return; + } + let slot = Slot { + seq: SEQ.fetch_add(1, Ordering::Relaxed), + tid: current_tid(), + description, + trace: StoredTrace::capture(None), + }; + let mut ledger = match LEDGER.lock() { + Ok(l) => l, + Err(poisoned) => poisoned.into_inner(), + }; + let history = &mut ledger[fd as usize]; + history.copy_within(0..HISTORY - 1, 1); + history[0] = slot; +} + +fn history_of(fd: i32) -> [Slot; HISTORY] { + if fd < 0 || fd as usize >= MAX_TRACKED_FD { + return [Slot::EMPTY; HISTORY]; + } + let ledger = match LEDGER.lock() { + Ok(l) => l, + Err(poisoned) => poisoned.into_inner(), + }; + ledger[fd as usize] +} + +/// Print the recorded close history of `fd`, newest first. +pub fn dump_history(fd: i32) { + let history = history_of(fd); + if history[0].seq == 0 { + eprintln!( + "fd {fd}: no successful close recorded through bun_sys (closed by C/C++ code, or never closed)" + ); + return; + } + for slot in history.iter().filter(|s| s.seq != 0) { + eprintln!( + "fd {fd} was closed successfully (close #{}, it was \"{}\") on tid {} at:", + slot.seq, + slot.description.as_str(), + slot.tid + ); + bun_core::dump_stack_trace(&slot.trace.trace(), DumpStackTraceOptions::default()); + } +} + +/// Print an EBADF report for a close attempt of `fd` made by `what`: the +/// current stack, then the close history of `fd`. +pub fn report_ebadf(what: &str, fd: i32) { + let now = StoredTrace::capture(None); + eprintln!("\n==================== close({fd}) = EBADF ({what}) ===================="); + eprintln!("this close attempt is on tid {} at:", current_tid()); + bun_core::dump_stack_trace(&now.trace(), DumpStackTraceOptions::default()); + dump_history(fd); + eprintln!("======================================================================\n"); +} + +/// Event-loop registration events (epoll add/del) per fd, same shape as the +/// close ledger. `kind` is a free-form label supplied by the event loop. +#[derive(Clone, Copy)] +struct RegSlot { + seq: u64, + tid: i64, + kind: [u8; 32], + description: FdDescription, + trace: StoredTrace, +} + +impl RegSlot { + const EMPTY: RegSlot = RegSlot { + seq: 0, + tid: 0, + kind: [0; 32], + description: FdDescription::UNKNOWN, + trace: StoredTrace::EMPTY, + }; +} + +const REG_HISTORY: usize = 6; + +static REGISTRATIONS: Mutex<[[RegSlot; REG_HISTORY]; MAX_TRACKED_FD]> = + Mutex::new([[RegSlot::EMPTY; REG_HISTORY]; MAX_TRACKED_FD]); + +/// Record an event-loop registration event for `fd` (`kind` is truncated to 32 bytes). +pub fn record_registration_event(kind: &str, fd: i32) { + if fd < 0 || fd as usize >= MAX_TRACKED_FD { + return; + } + let mut slot = RegSlot { + seq: SEQ.fetch_add(1, Ordering::Relaxed), + tid: current_tid(), + kind: [0; 32], + description: FdDescription::of(fd), + trace: StoredTrace::capture(None), + }; + let n = kind.len().min(32); + slot.kind[..n].copy_from_slice(&kind.as_bytes()[..n]); + let mut table = match REGISTRATIONS.lock() { + Ok(t) => t, + Err(poisoned) => poisoned.into_inner(), + }; + let history = &mut table[fd as usize]; + history.copy_within(0..REG_HISTORY - 1, 1); + history[0] = slot; +} + +fn dump_registration_events(fd: i32) { + if fd < 0 || fd as usize >= MAX_TRACKED_FD { + return; + } + let history = { + let table = match REGISTRATIONS.lock() { + Ok(t) => t, + Err(poisoned) => poisoned.into_inner(), + }; + table[fd as usize] + }; + if history[0].seq == 0 { + eprintln!("fd {fd}: no event-loop registration events recorded"); + return; + } + for slot in history.iter().filter(|s| s.seq != 0) { + let len = slot + .kind + .iter() + .position(|&b| b == 0) + .unwrap_or(slot.kind.len()); + eprintln!( + "fd {fd} registration event #{}: {} (fd was \"{}\") on tid {} at:", + slot.seq, + core::str::from_utf8(&slot.kind[..len]).unwrap_or("?"), + slot.description.as_str(), + slot.tid + ); + bun_core::dump_stack_trace(&slot.trace.trace(), DumpStackTraceOptions::default()); + } +} + +/// Print the current stack plus what `fd`, stdout and stderr point at, the +/// registration events recorded for `fd`, and its close history. Used to +/// report failures to register `fd` with the event loop. +pub fn report_fd_event(what: &str, fd: i32) { + let now = StoredTrace::capture(None); + eprintln!("\n==================== {what} ===================="); + eprintln!( + "fd {fd} is \"{}\"; fd 1 is \"{}\"; fd 2 is \"{}\"; tid {}", + FdDescription::of(fd).as_str(), + FdDescription::of(1).as_str(), + FdDescription::of(2).as_str(), + current_tid() + ); + eprintln!("at:"); + bun_core::dump_stack_trace(&now.trace(), DumpStackTraceOptions::default()); + dump_registration_events(fd); + dump_history(fd); + eprintln!("======================================================================\n"); +} diff --git a/src/sys/fd.rs b/src/sys/fd.rs index 4e423c09f294..c867c75de731 100644 --- a/src/sys/fd.rs +++ b/src/sys/fd.rs @@ -101,6 +101,9 @@ impl FdExt for Fd { &fd_fmt_buf[..len] }; + #[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] + let description = sys::close_ledger::FdDescription::of(self.native()); + let result: Option = { #[cfg(any(target_os = "linux", target_os = "android"))] { @@ -195,6 +198,14 @@ impl FdExt for Fd { #[cfg(debug_assertions)] { + #[cfg(any(target_os = "linux", target_os = "android"))] + match result { + Some(ref err) if err.errno == sys::E::EBADF as _ => { + sys::close_ledger::report_ebadf("FdExt::close", self.native()); + } + Some(_) => {} + None => sys::close_ledger::record_closed(self.native(), description), + } if let Some(ref err) = result { if err.errno == sys::E::EBADF as _ { bun_core::debug_warn!( diff --git a/src/sys/lib.rs b/src/sys/lib.rs index b4b8f766985e..ad2c9caa629f 100644 --- a/src/sys/lib.rs +++ b/src/sys/lib.rs @@ -17,6 +17,8 @@ pub extern crate bun_core as bun_str; pub extern crate bun_libuv_sys; pub mod fd; pub use fd::{ErrorCase, FdExt, MakeLibUvOwnedError, RawFd}; +#[cfg(all(debug_assertions, any(target_os = "linux", target_os = "android")))] +pub mod close_ledger; #[path = "Error.rs"] mod error; pub use error::Error; @@ -2007,11 +2009,19 @@ mod posix_impl { // Darwin uses `close$NOCANCEL` (avoid pthread cancellation point). #[cfg(any(target_os = "linux", target_os = "android"))] { + #[cfg(debug_assertions)] + let description = crate::close_ledger::FdDescription::of(fd.native()); return match super::linux_syscall::close(fd.native()) { Err(e) if e == libc::EBADF => { + #[cfg(debug_assertions)] + crate::close_ledger::report_ebadf("bun_sys::close", fd.native()); Err(Error::from_code_int(libc::EBADF, Tag::close).with_fd(fd)) } - _ => Ok(()), + _ => { + #[cfg(debug_assertions)] + crate::close_ledger::record_closed(fd.native(), description); + Ok(()) + } }; } #[cfg(not(any(target_os = "linux", target_os = "android")))]