One info! line in a TLS destructor aborted the host on every session teardown #289

Merged
enricobuehler merged 1 commits from worktree-win-teardown-abort into main 2026-08-18 08:43:32 +00:00
2 changed files with 53 additions and 13 deletions
+19 -4
View File
@@ -148,14 +148,28 @@ mod imp {
/// place used to be the design ("reverts at process exit") — but the host is a 24/7 service,
/// so after one stream it competed at HIGH class with a 1 ms global timer against whatever
/// the user played locally, forever.
///
/// 🛑 **Nothing in here may log, or touch anything that logs.** This runs from
/// [`HotThreadGuard`]'s `Drop`, which is a **TLS destructor** — and by then this thread's
/// *other* thread-locals may already be gone, including the ones `tracing_subscriber`'s
/// registry keeps (it is `sharded-slab`-backed, and the slab's per-thread registration is a
/// `thread_local!` read with `LocalKey::with`). Emitting an event here panicked with "cannot
/// access a Thread Local Storage value during or after destruction", and **a panic that
/// escapes a TLS destructor is fatal in Rust** — `fatal runtime error: thread local panicked
/// on drop, aborting`. So one `info!` line killed the whole host on session teardown and the
/// SCM restarted it ~6 s later, which read in the field as a mystery reconnect (on glass,
/// .173: four aborts, every one of them a session teardown).
///
/// The revert itself is only FFI and stays here, inside the refcount lock, so it remains
/// atomic against a session starting concurrently. The counterpart "applied" line in
/// [`tune_process`] runs on a live thread and is kept — that one is safe.
fn untune_process() {
// SAFETY: same FFI surface as `tune_process` — plain-integer arguments, constant
// pseudo-handle, no pointers or buffers.
// pseudo-handle, no pointers or buffers. Sound in a TLS destructor: no Rust TLS is read.
unsafe {
timeEndPeriod(1); // pairs the timeBeginPeriod(1)
DwmEnableMMCSS(0);
SetPriorityClass(GetCurrentProcess(), NORMAL_PRIORITY_CLASS);
tracing::info!("windows session tuning reverted (timer, DWM MMCSS, NORMAL priority)");
}
}
@@ -165,8 +179,9 @@ mod imp {
impl Drop for HotThreadGuard {
fn drop(&mut self) {
// A poisoned lock skips the revert (best-effort, like every call here) instead of
// panicking inside a TLS destructor.
// ⚠ TLS DESTRUCTOR. Everything reached from here must be panic-free and must not log —
// see [`untune_process`] for what a single `info!` here cost. A poisoned lock skips the
// revert (best-effort, like every call here) rather than panicking.
if let Ok(mut n) = HOT_THREADS.lock() {
*n -= 1;
if *n == 0 {
+34 -9
View File
@@ -190,10 +190,25 @@ fn main() {
);
}
// Tee every panic through `tracing` BEFORE the default hook: a panicking thread otherwise
// Tee every panic into the log ring BEFORE the default hook: a panicking thread otherwise
// prints only to stderr — absent from the web console's Logs tab (the ring) and gone entirely
// when stderr is detached — so a field report reads "host died, zero errors in the logs".
// The default hook still runs afterwards for the usual stderr message/abort behavior.
//
// 🛑 **The tee goes straight to the ring, NOT through `tracing`.** A panic hook that emits a
// tracing event is a trap: `tracing_subscriber`'s registry is `sharded-slab`-backed and reads a
// `thread_local!` with `LocalKey::with`, so emitting from a thread whose TLS is being torn down
// panics — *inside the hook*. Rust treats a panic raised while the hook is running as
// `MustAbort::PanicInHook` and then deliberately does not format the message ("perhaps that is
// causing the panic"), so the log gets `panicked at <loc>:` followed by a BLANK line and
// `thread panicked while processing panic. aborting.` — the cause erased at exactly the moment
// it mattered. That is precisely what hid the 2026-08-18 teardown abort on .173 (four aborts,
// zero diagnosis) until it was reproduced standalone.
//
// Everything below is TLS-free and cannot panic: `LogRing` is a `OnceLock` + `Mutex`, and
// `thread::current().name()` / `Backtrace::force_capture()` were both verified safe during TLS
// destruction. This does not make a TLS-destructor panic survivable — Rust aborts on those
// regardless — but it does mean the message that names the cause always lands.
let default_panic = std::panic::take_hook();
std::panic::set_hook(Box::new(move |info| {
// Manual payload downcast (`payload_as_str` needs Rust 1.91; workspace MSRV is 1.82).
@@ -203,14 +218,24 @@ fn main() {
.copied()
.or_else(|| info.payload().downcast_ref::<String>().map(String::as_str))
.unwrap_or("<non-string panic payload>");
tracing::error!(
thread = std::thread::current().name().unwrap_or("<unnamed>"),
location = %info
.location()
.map(ToString::to_string)
.unwrap_or_else(|| "<unknown>".into()),
backtrace = %std::backtrace::Backtrace::force_capture(),
"PANIC: {payload}"
let location = info
.location()
.map(ToString::to_string)
.unwrap_or_else(|| "<unknown>".into());
let thread = std::thread::current()
.name()
.unwrap_or("<unnamed>")
.to_string();
let backtrace = std::backtrace::Backtrace::force_capture();
let ts_ms = std::time::SystemTime::now()
.duration_since(std::time::UNIX_EPOCH)
.map(|d| d.as_millis() as u64)
.unwrap_or(0);
log_capture::ring().push_remote(
"ERROR",
"punktfunk_host::panic",
&format!("PANIC: {payload} (thread={thread}, at {location})\n{backtrace}"),
ts_ms,
);
default_panic(info);
}));