From 106bda2e8b39091fcdacca343f6037e40a23d658 Mon Sep 17 00:00:00 2001 From: reverse Date: Thu, 27 Aug 2026 16:32:48 +0000 Subject: [PATCH] watchdog: name the slow event/command in the slow-event snote and [watchdog] warning --- src/ircd.rs | 73 ++++++++++++++++++++++++++++++++++++++++++++++++++--- src/main.rs | 10 +++++--- 2 files changed, 76 insertions(+), 7 deletions(-) diff --git a/src/ircd.rs b/src/ircd.rs index 753e5ae..ba12083 100644 --- a/src/ircd.rs +++ b/src/ircd.rs @@ -120,6 +120,55 @@ fn with_extra_tag(line: &str, tag: &str) -> String { } } +/// A short human label for an event, appended to `out` (cleared by the caller). Used +/// by the slow-event snote and the [watchdog] warning so a stall names its culprit +/// (which command / connect / background result) rather than only a duration. Writes +/// in place, so it costs no allocation on the hot path once `out`'s buffer is warm. +fn write_event_label(ev: &Event, out: &mut String) { + use std::fmt::Write; + match ev { + Event::Connect { addr, link, outbound, .. } => { + if *link { + let _ = write!(out, "server link ({})", if *outbound { "outbound" } else { "inbound" }); + } else { + let _ = write!(out, "connect from {}", addr.ip()); + } + } + Event::Line { line, .. } => push_verb(line, out), + Event::Disconnect { .. } => out.push_str("disconnect"), + Event::ResolvedHost { .. } => out.push_str("DNS/DNSBL result"), + Event::Ident { .. } => out.push_str("ident result"), + Event::OperAuth { .. } => out.push_str("OPER auth result"), + Event::MkpasswdResult { .. } => out.push_str("MKPASSWD result"), + Event::TitleAuth { .. } => out.push_str("TITLE auth result"), + Event::ConnclassAuth { .. } => out.push_str("connect-class auth result"), + Event::HttpResult { tag, .. } => { + let _ = write!(out, "HTTP result [{tag}]"); + } + Event::RpcRequest { method, .. } => { + let _ = write!(out, "RPC {method}"); + } + Event::Tick => out.push_str("tick (ping/idle sweep)"), + Event::Rehash => out.push_str("rehash"), + } +} + +/// Append the IRC command verb of a raw client line (skipping IRCv3 `@tags` and any +/// `:prefix`), upper-cased and length-bounded so a malformed line can't bloat the label. +fn push_verb(line: &str, out: &mut String) { + let mut s = line.trim_start(); + if let Some(rest) = s.strip_prefix('@') { + s = rest.split_once(' ').map_or("", |(_, r)| r).trim_start(); + } + if let Some(rest) = s.strip_prefix(':') { + s = rest.split_once(' ').map_or("", |(_, r)| r).trim_start(); + } + match s.split_whitespace().next() { + Some(verb) => out.extend(verb.chars().take(24).flat_map(char::to_uppercase)), + None => out.push_str("(empty line)"), + } +} + pub struct Ircd { server: Server, commands: HashMap<&'static str, Box>, @@ -158,9 +207,23 @@ impl Ircd { /// `busy` is a shared marker the watchdog thread samples: it holds the ms-since- /// `base` at which the current event started (0 = idle), so a stuck handler is /// visible from outside. Events slower than `slow_command_ms` are also snoticed. - pub fn run(mut self, rx: Receiver, busy: Arc, base: Instant) { + pub fn run( + mut self, + rx: Receiver, + busy: Arc, + base: Instant, + label: Arc>, + ) { let slow_ms = self.server.conf_num("slow_command_ms", 200u64); for ev in rx { + // record what this event is into the buffer the watchdog samples, so a + // slow or stuck event names its culprit instead of just a duration. Writes + // into the reused String — no per-event allocation once the buffer is warm. + { + let mut g = label.lock().unwrap_or_else(|e| e.into_inner()); + g.clear(); + write_event_label(&ev, &mut g); + } busy.store((base.elapsed().as_millis() as u64).max(1), Ordering::Relaxed); let start = Instant::now(); if std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| self.handle_event(ev))) @@ -176,10 +239,12 @@ impl Ircd { busy.store(0, Ordering::Relaxed); let ms = start.elapsed().as_millis() as u64; if slow_ms != 0 && ms >= slow_ms { + let what = label.lock().unwrap_or_else(|e| e.into_inner()).clone(); let ms_s = ms.to_string(); - let m = self - .server - .trf("slow event: a command took {0}ms on the core thread", &[ms_s.as_str()]); + let m = self.server.trf( + "slow event: {0} took {1}ms on the core thread", + &[what.as_str(), ms_s.as_str()], + ); self.server.snotice(&m); } } diff --git a/src/main.rs b/src/main.rs index b380808..ebc4945 100644 --- a/src/main.rs +++ b/src/main.rs @@ -250,24 +250,28 @@ fn main() { // (0 = idle); a separate thread warns if it stays stuck past `watchdog_ms`. let wd_base = Instant::now(); let core_busy = Arc::new(AtomicU64::new(0)); + // the core writes a short label of the current event here; the watchdog and the + // slow-event snote read it so a stall names its culprit, not just a duration. + let core_label = Arc::new(std::sync::Mutex::new(String::new())); let watchdog_ms = raw_num("watchdog_ms", 5000) as u64; // 0 = off if watchdog_ms > 0 { - let (wb, base) = (core_busy.clone(), wd_base); + let (wb, base, wl) = (core_busy.clone(), wd_base, core_label.clone()); thread::spawn(move || loop { thread::sleep(Duration::from_millis(1000)); let cur = wb.load(Ordering::Relaxed); if cur != 0 { let stuck = (base.elapsed().as_millis() as u64).saturating_sub(cur); if stuck > watchdog_ms { + let what = wl.lock().map(|g| g.clone()).unwrap_or_else(|e| e.into_inner().clone()); eprintln!( - "[watchdog] core thread stuck ~{stuck}ms on one event — a handler is blocking the whole server" + "[watchdog] core thread stuck ~{stuck}ms on '{what}' — a handler is blocking the whole server" ); } } }); } let (busy, base) = (core_busy, wd_base); - let core = thread::spawn(move || Ircd::new(core_cfg, core_tx, core_counter).run(rx, busy, base)); + let core = thread::spawn(move || Ircd::new(core_cfg, core_tx, core_counter).run(rx, busy, base, core_label)); // background timer: drives ping/idle timeouts let tick_tx = tx.clone();