detcore/util.rs
1/*
2 * Copyright (c) Meta Platforms, Inc. and affiliates.
3 * All rights reserved.
4 *
5 * This source code is licensed under the BSD-style license found in the
6 * LICENSE file in the root directory of this source tree.
7 */
8
9//! Widely useful small utilities.
10
11use std::sync::OnceLock;
12use std::sync::atomic::AtomicU64;
13use std::sync::atomic::Ordering;
14use std::time::Duration;
15
16use crate::types::NANOS_PER_RCB;
17
18#[allow(dead_code)]
19/// A simple debugging helper function that makes it easy to printf-debug through
20/// layers of stdout/stderr caputure, such as when running under buck test/tpx.
21pub fn punch_out_print(msg: &str) {
22 use std::io::Write;
23 // TODO: if we want this to be more performant, we can have a lazy static
24 // global file handle for this. This, however, keeps it simple for occasional usage.œ
25 if let Ok(mut tty) = std::fs::OpenOptions::new()
26 .read(true)
27 .write(true)
28 .open("/dev/tty")
29 {
30 writeln!(tty, "{}", msg).unwrap();
31 } else {
32 // If devtty doesn't exist, we just use stderr.
33 eprintln!("{}", msg);
34 }
35}
36/// A helper function to convert a number of Retired Conditional Branches (RCBS) into
37/// a `std::time::Duration` via the `NANOS_PER_RCB` defined in ` types.rs`.
38pub fn rcbs_to_duration(rcbs: u64) -> Duration {
39 Duration::from_nanos((rcbs as f64 * NANOS_PER_RCB) as u64)
40}
41
42/// A little better than the builtin string truncation in format strings, because it includes ellipses.
43// TODO: There should be some advanced solution for printing potentially huge things that
44// doesn't actually render them all...
45pub fn truncated(width: usize, mut s: String) -> String {
46 if s.len() > width {
47 if width >= 3 {
48 s.truncate(width - 3);
49 s.push_str("...");
50 s
51 } else {
52 s.truncate(width);
53 s
54 }
55 } else {
56 s
57 }
58}
59
60/// A `Write` for the supervisor's own diagnostics on fd 2 that survives a
61/// NONBLOCKING description.
62///
63/// ⚠️ THE GUEST CAN SET `O_NONBLOCK` ON HERMIT'S STDERR AND SILENTLY CUT THE
64/// SUPERVISOR'S ERROR CHANNEL. fd 2 is an INHERITED open file description shared
65/// with the guest, so `fcntl(2, F_SETFL, O_NONBLOCK)` in the guest changes the
66/// behaviour of hermit's OWN later writes. Measured 2026-08-26 on a 4096-byte
67/// pipe under back-pressure, `hermit --log info run -- <guest>`:
68///
69/// ```text
70/// control guest (touches nothing) rc=0 138 lines, ends on the run summary
71/// guest sets O_NONBLOCK on fd 2 rc=101 134 lines, ends mid-log
72/// ```
73///
74/// The summary was emitted by `eprint!`, which calls `write_all`; `write_all`
75/// does NOT retry `EAGAIN`, so it returns an error and the print macro PANICS.
76/// The panic message then went to the same full pipe and was lost as well, so
77/// the delivered output contained no panic text, no error, and no marker of any
78/// kind -- it simply stopped on a plausible-looking line. Exit 101 was the only
79/// surviving evidence, and a caller that reads output rather than status sees a
80/// short report, not a truncated one.
81///
82/// ⚠️ WAIT, DO NOT SPIN, AND DO NOT CLEAR THE FLAG. Clearing `O_NONBLOCK` would
83/// change what the guest observes on a descriptor it legitimately shares; this
84/// leaves the flag exactly as the guest set it and simply waits for the pipe to
85/// drain, which is what a blocking write would have done. A bare retry loop
86/// would busy-spin against a full pipe, so it blocks in `poll(POLLOUT)`.
87pub struct RetryingStderr;
88
89/// Total wall-clock ALL diagnostic writes in ONE PROCESS may spend waiting for a
90/// reader that is not draining. Hermit forks, so read the fork note below before
91/// treating this as the whole exit path's budget.
92///
93/// ⚠️ WITHOUT A CEILING THIS LOOP NEVER ENDS, AND IT RUNS WHILE HERMIT IS ALREADY
94/// FAILING. `EAGAIN` -> `poll(POLLOUT, 1s)` -> retry is correct for a reader that
95/// is SLOW and unbounded for a reader that is STOPPED. Measured 2026-08-26 on a
96/// 4096-byte pipe filled to 3900 with `O_NONBLOCK` set, where nothing ever reads:
97///
98/// ```text
99/// before RetryingStderr (eprintln!) EXITED rc=101 immediately
100/// RetryingStderr, no ceiling STILL RUNNING after 25s, no exit
101/// ```
102///
103/// The first is wrong loudly; the second does not return at all, on the path that
104/// reports why hermit is stopping. A supervisor that hangs while reporting an
105/// error is harder to diagnose than one that dies reporting it badly.
106///
107/// ⚠️ THIS IS A TOTAL FOR THE WHOLE PROCESS, NOT A BUDGET PER `write()` CALL, AND
108/// THE DIFFERENCE IS THE ENTIRE GUARANTEE. An earlier version started the clock
109/// inside `fn write`, so every call got the full allowance. Nothing writes to
110/// stderr exactly once on the exit path:
111///
112/// ```text
113/// hermit-cli/src/bin/hermit/main.rs the failure class, the head of the
114/// error chain, then ONE PER CAUSE in
115/// `for cause in chain` -- 2 + chain length
116/// hermit-cli/src/bin/hermit/tracing.rs .with_writer(|| RetryingStderr) is the
117/// writer for the WHOLE subscriber: one
118/// write per log event
119/// detcore/src/tool_global.rs a multi-part `write!`, which `write_fmt`
120/// splits into several `write` calls
121/// ```
122///
123/// With a per-call budget the process-level cost was N times this number, N is
124/// bounded by the error chain rather than by anything here, and every caller's
125/// `let _ =` swallowed the overrun silently. A `--log info` run measured at 138
126/// lines would have been minutes, not seconds.
127///
128/// ⚠️ THE VALUE IS DERIVED FROM THE BOUND THAT ENCLOSES IT, NOT CHOSEN. Diagnostics
129/// on the exit path run inside `RUN_TIMEOUT_UNWIND_GRACE` (10s,
130/// `hermit-cli/src/lib.rs`): the window between a `--timeout` expiring and the
131/// SIGALRM fallback calling `_exit`. Overrun there does not merely delay the
132/// report, it loses it -- the fallback fires mid-sentence and additionally emits
133/// `HERMIT_RUN_TIMEOUT_FALLBACK`, which is supposed to mean the teardown wedged.
134/// So the arithmetic is:
135///
136/// ⚠️ IT USED TO APPLY ONCE PER PROCESS, BECAUSE HERMIT FORKS. `Container::run`
137/// forks the container init, which got its own COPY of the process-wide clock and
138/// spent its own full deadline; both write diagnostics to the same fd 2 on the way
139/// out. Measured 2026-08-26 against a stopped reader on a real guest, which is the
140/// case where both processes report:
141///
142/// ```text
143/// deadline 5000ms -> 10.03s observed two processes, one deadline each
144/// deadline 2500ms -> 5.02s observed the same two, halved
145/// deadline 2500ms -> 2.52s observed missing guest: only ONE process reports
146/// ```
147///
148/// ⚠️ AND THE MULTIPLIER WAS NOT ALWAYS TWO, WHICH IS WHY IT IS NO LONGER A
149/// CONSTANT. `hermit run --verify` runs the guest twice and forks once per run, so
150/// it is the outer hermit plus TWO container inits -- three writers, and siblings
151/// rather than a chain. From the call structure, so it needs no sampling:
152///
153/// ```text
154/// run.rs fn verify() Run1 -> self.run_verify(..) Run2 -> self.run_verify(..)
155/// fn run_verify() -> with_container(..) forks a container init
156/// ```
157///
158/// At three, `3 x 2500ms x 2 = 15s` against a 10s grace: the stated split does not
159/// hold. Correcting the constant to three would force the deadline to ~1666ms and
160/// leave a hardcoded count for the next differently-forking path to falsify.
161///
162/// So the ORIGIN is shared across the invocation instead (see
163/// `STDERR_ORIGIN_ADDR`): every hermit process measures from the same start, the
164/// invocation spends ONE deadline however many processes write, and the count
165/// stops being an input. The arithmetic no longer contains it:
166///
167/// ```text
168/// RUN_TIMEOUT_UNWIND_GRACE 10s the enclosing bound
169/// diagnostics may have half of it 5s leaving 5s for the unwind
170/// this deadline, per INVOCATION 2500ms comfortably inside the 5s
171/// ```
172///
173/// Half is a split, not a measurement, and is stated as one. What is ALSO measured is
174/// that the previous arrangement could not fit: at 5s per CALL, the same real-guest
175/// fixture took 15.04s -- three blocked writes -- against a 10s grace, so the inner
176/// bound exceeded its outer bound before any unwind work happened at all.
177/// `hermit-cli` asserts this relationship in a test, so raising either side without
178/// the other fails by name.
179///
180/// On expiry the write returns `WouldBlock`, `writeln!` gives up, the caller's
181/// `let _ =` drops that line, and hermit exits — the pre-existing contract for a
182/// diagnostic that cannot be delivered.
183pub const STDERR_DIAGNOSTIC_DEADLINE: std::time::Duration = std::time::Duration::from_millis(2500);
184
185/// When this process first found stderr unwritable, shared by every
186/// `RetryingStderr`, which is what makes the deadline above a process total.
187/// Set on the first `EAGAIN` and never reset: a run that recovers and later
188/// blocks again has still spent that earlier time on its exit path.
189///
190/// Fallback only: used when the invocation-wide origin below is unavailable.
191static STDERR_BLOCKED_SINCE: std::sync::OnceLock<std::time::Instant> = std::sync::OnceLock::new();
192
193/// The same instant, shared by every hermit process of ONE INVOCATION.
194///
195/// ⚠️ WITHOUT THIS THE DEADLINE IS MULTIPLIED BY THE NUMBER OF PROCESSES, AND
196/// THAT NUMBER IS NOT 2. A `static` lives per process, so each hermit sets its
197/// own origin and spends its own full deadline. The comment above states the
198/// multiplier as "2 -- hermit + the forked init", which is right for `hermit
199/// run` and wrong for `hermit run --verify`. From the call structure, not from
200/// sampling a process table:
201///
202/// ```text
203/// hermit-cli/src/bin/hermit/run.rs
204/// fn verify() -> Run1: self.run_verify(log1_file, global)
205/// -> Run2: self.run_verify(log2_file, global)
206/// fn run_verify() -> with_container(..) forks a container init
207/// ```
208///
209/// So `--verify` is the outer hermit plus TWO container inits, which share the
210/// outer as their parent. Three writing processes, and siblings rather than a
211/// chain. `record --verify` forks twice for the same reason, at
212/// `record_verify.record` and `record_verify.replay` in record_start.rs.
213///
214/// At three the stated derivation does not hold: 3 x 2500ms x 2 = 15s against a
215/// 10s grace. Correcting the constant to 3 would force the deadline to ~1666ms
216/// and would leave a hardcoded count that the next differently-forking path
217/// falsifies again. Sharing the ORIGIN makes the multiplier 1 by construction --
218/// every process measures from the same start, so the invocation spends one
219/// deadline however many processes write -- and the count stops being an input.
220///
221/// ⚠️ THE CARRIER IS AN INHERITED SHARED MAPPING, DELIBERATELY NOT AN ENVIRONMENT
222/// VARIABLE AND NOT A FILE. A variable set on hermit reaches the GUEST by default
223/// (`BaseEnv::Host` does not clear it), and a per-run-varying value visible to the
224/// guest, in a determinism tool, on a surface the argv/env hashing covers, would
225/// be a worse defect than the one being fixed. A file would put I/O on the path
226/// that runs while hermit is already failing. `exec` drops the mapping, so the
227/// guest never shares it.
228///
229/// `CLOCK_MONOTONIC` rather than `Instant`: an `Instant` is not meaningful in
230/// another process, while `CLOCK_MONOTONIC` is system-wide on Linux, so the same
231/// nanosecond count is directly comparable between parent and child. 0 means
232/// unset; the first blocked write in ANY process installs the origin.
233static STDERR_ORIGIN_ADDR: OnceLock<usize> = OnceLock::new();
234
235/// Create the origin cell every hermit process of this invocation shares.
236///
237/// ⚠️ MUST BE CALLED BEFORE THE FIRST FORK, and is called from the top of `main`.
238/// A mapping made after a fork is not shared with the child that already exists,
239/// so a late call would silently give each process its own origin -- the exact
240/// failure this removes. `main` dominates every `with_container` and
241/// `run_guarded_at` site in run.rs, replay.rs and record_start.rs.
242pub fn init_shared_stderr_deadline_origin() {
243 STDERR_ORIGIN_ADDR.get_or_init(|| {
244 // SAFETY: an anonymous shared mapping of one page, no fd, no fixed
245 // address. Never unmapped: it must outlive every child, and one page per
246 // invocation does not justify a teardown path on an exit route.
247 let addr = unsafe {
248 libc::mmap(
249 std::ptr::null_mut(),
250 std::mem::size_of::<AtomicU64>(),
251 libc::PROT_READ | libc::PROT_WRITE,
252 libc::MAP_SHARED | libc::MAP_ANONYMOUS,
253 -1,
254 0,
255 )
256 };
257 if addr == libc::MAP_FAILED {
258 // Not fatal and NOT silent: `stderr_deadline_is_shared` reports false
259 // and the per-process fallback still bounds each process.
260 return 0;
261 }
262 // SAFETY: freshly mapped, aligned for u64, sole owner at this point.
263 unsafe { (addr as *mut AtomicU64).write(AtomicU64::new(0)) };
264 addr as usize
265 });
266}
267
268fn shared_origin_cell() -> Option<&'static AtomicU64> {
269 match STDERR_ORIGIN_ADDR.get() {
270 None | Some(0) => None,
271 // SAFETY: the address came from `mmap` above, was initialised there, is
272 // never unmapped, and `AtomicU64` is safe to share across processes in a
273 // `MAP_SHARED` page.
274 Some(&addr) => Some(unsafe { &*(addr as *const AtomicU64) }),
275 }
276}
277
278fn monotonic_nanos() -> u64 {
279 let mut ts = libc::timespec {
280 tv_sec: 0,
281 tv_nsec: 0,
282 };
283 // SAFETY: one initialised `timespec`, a clock id the kernel always supports.
284 unsafe { libc::clock_gettime(libc::CLOCK_MONOTONIC, &mut ts) };
285 (ts.tv_sec as u64) * 1_000_000_000 + (ts.tv_nsec as u64)
286}
287
288/// Whether the deadline is bounded per INVOCATION or only per process.
289///
290/// ⚠️ EXISTS SO THE WEAKER STATE CANNOT BE SILENT. If the mapping failed, or
291/// something forks before `init_shared_stderr_deadline_origin`, the bound
292/// degrades to per-process and is multiplied by however many processes write.
293#[doc(hidden)]
294pub fn stderr_deadline_is_shared() -> bool {
295 shared_origin_cell().is_some()
296}
297
298/// How long this invocation has been blocked on stderr, from the shared origin
299/// when there is one and from this process's own first block otherwise.
300fn stderr_blocked_for() -> std::time::Duration {
301 match shared_origin_cell() {
302 Some(cell) => {
303 let now = monotonic_nanos();
304 // The first blocked write in ANY process installs the origin; every
305 // later one, in any process, reads the value that won.
306 let origin = match cell.compare_exchange(0, now, Ordering::AcqRel, Ordering::Acquire) {
307 Ok(_) => now,
308 Err(existing) => existing,
309 };
310 std::time::Duration::from_nanos(now.saturating_sub(origin))
311 }
312 None => STDERR_BLOCKED_SINCE
313 .get_or_init(std::time::Instant::now)
314 .elapsed(),
315 }
316}
317
318/// Reset the shared origin. Test-only: brackets that measure the deadline need
319/// each case to start from zero, and nothing in a real run wants this.
320#[doc(hidden)]
321pub fn reset_stderr_deadline_origin_for_test() {
322 if let Some(cell) = shared_origin_cell() {
323 cell.store(0, Ordering::Release);
324 }
325}
326
327impl std::io::Write for RetryingStderr {
328 fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
329 if buf.is_empty() {
330 return Ok(0);
331 }
332 loop {
333 // SAFETY: `write(2)` on fd 2 reads `buf.len()` bytes from `buf`,
334 // which is valid for that length, and writes no memory.
335 let n = unsafe { libc::write(libc::STDERR_FILENO, buf.as_ptr().cast(), buf.len()) };
336 if n >= 0 {
337 return Ok(n as usize);
338 }
339 let err = std::io::Error::last_os_error();
340 match err.kind() {
341 std::io::ErrorKind::Interrupted => continue,
342 std::io::ErrorKind::WouldBlock => {
343 // ⚠️ BOUNDED, AND THE CLOCK IS PROCESS-WIDE. Waiting for a slow
344 // reader is the point; waiting for a stopped one is a hang on
345 // hermit's exit path. Starting the clock here rather than at the
346 // top of `write` is what makes the deadline a total: the first
347 // blocked write sets it and every later one inherits it, so N
348 // writes cost the deadline once instead of N times.
349 // Measured from the origin shared by every hermit process
350 // of this invocation when there is one, so N processes spend
351 // ONE deadline rather than N. See STDERR_ORIGIN_ADDR.
352 let spent = stderr_blocked_for();
353 let Some(remaining) = STDERR_DIAGNOSTIC_DEADLINE.checked_sub(spent) else {
354 return Err(err);
355 };
356 // Block until the reader makes room. A failed or timed-out
357 // poll falls through to another write attempt rather than
358 // dropping the bytes.
359 let mut pfd = libc::pollfd {
360 fd: libc::STDERR_FILENO,
361 events: libc::POLLOUT,
362 revents: 0,
363 };
364 // ⚠️ CLAMPED TO WHAT IS LEFT, NOT A FLAT SECOND. The check above
365 // happens BEFORE the poll, so a flat 1000ms let a call that
366 // started at 4.9s sleep a further second and overshoot to ~6s --
367 // the deadline documented one number and delivered another.
368 // Clamping makes the elapsed total the stated total.
369 let timeout_ms = i32::try_from(remaining.as_millis())
370 .unwrap_or(i32::MAX)
371 .min(1000);
372 // SAFETY: one initialised `pollfd`, count 1, timeout in ms.
373 unsafe {
374 libc::poll(&mut pfd, 1, timeout_ms);
375 }
376 continue;
377 }
378 _ => return Err(err),
379 }
380 }
381 }
382
383 fn flush(&mut self) -> std::io::Result<()> {
384 Ok(())
385 }
386}
387
388#[cfg(test)]
389mod shared_stderr_origin_tests {
390 use super::*;
391
392 /// ⚠️ THESE TESTS SHARE ONE PROCESS-GLOBAL CELL, SO THEY MUST NOT RUN AT THE
393 /// SAME TIME. That is the point of the cell -- it is shared -- but it makes the
394 /// tests interfere: one resets the origin while another is timing from it.
395 /// Found the honest way: they passed under `--test-threads 1` and failed in the
396 /// real suite, so the single-threaded run was not evidence about the suite.
397 static SERIALISE: std::sync::Mutex<()> = std::sync::Mutex::new(());
398
399 fn exclusive() -> std::sync::MutexGuard<'static, ()> {
400 SERIALISE.lock().unwrap_or_else(|e| e.into_inner())
401 }
402
403 /// The origin must actually be SHARED across a fork, or nothing else holds.
404 ///
405 /// ⚠️ THIS IS THE ONE THING THAT CANNOT BE CHECKED BY READING THE CODE.
406 /// `MAP_SHARED` versus `MAP_PRIVATE` is a single token; get it wrong and every
407 /// single-process test still passes while each container init silently gets its
408 /// own deadline again -- the exact defect this removes. So this forks for real
409 /// and checks that a value written by the child is visible in the parent.
410 #[test]
411 fn the_origin_is_shared_across_a_fork() {
412 let _exclusive = exclusive();
413 init_shared_stderr_deadline_origin();
414 let cell = shared_origin_cell().expect("mapping must exist after init");
415 cell.store(0, Ordering::Release);
416
417 // SAFETY: the child does no allocation and no locking -- one atomic store
418 // and `_exit` -- so forking from a test harness thread is safe here.
419 let pid = unsafe { libc::fork() };
420 assert!(pid >= 0, "fork failed");
421 if pid == 0 {
422 shared_origin_cell()
423 .expect("child inherited no mapping")
424 .store(4242, Ordering::Release);
425 unsafe { libc::_exit(0) };
426 }
427 let mut status = 0;
428 assert_eq!(
429 unsafe { libc::waitpid(pid, &mut status, 0) },
430 pid,
431 "waitpid"
432 );
433 assert_eq!(status, 0, "child exited nonzero");
434
435 assert_eq!(
436 cell.load(Ordering::Acquire),
437 4242,
438 "the parent cannot see the child's write, so each container init would \
439 start its OWN deadline and the invocation would spend one per process -- \
440 check MAP_SHARED in init_shared_stderr_deadline_origin"
441 );
442 cell.store(0, Ordering::Release);
443 }
444
445 /// The first blocked write installs the origin; later ones inherit it.
446 ///
447 /// This is what makes the deadline a TOTAL rather than a fresh allowance per
448 /// caller, and it must hold across processes, not just across calls.
449 #[test]
450 fn the_first_writer_installs_the_origin_and_others_inherit_it() {
451 let _exclusive = exclusive();
452 init_shared_stderr_deadline_origin();
453 reset_stderr_deadline_origin_for_test();
454 let cell = shared_origin_cell().expect("mapping must exist after init");
455
456 let first = stderr_blocked_for();
457 let installed = cell.load(Ordering::Acquire);
458 assert_ne!(installed, 0, "the first call must install a nonzero origin");
459 // A fresh origin means almost no time has been spent yet.
460 assert!(
461 first < Duration::from_millis(50),
462 "first call saw {first:?}"
463 );
464
465 std::thread::sleep(Duration::from_millis(20));
466 let second = stderr_blocked_for();
467 assert_eq!(
468 cell.load(Ordering::Acquire),
469 installed,
470 "a later call moved the origin, so each caller would get a fresh \
471 allowance and the deadline would stop being a total"
472 );
473 assert!(
474 second >= Duration::from_millis(15),
475 "the second call reported {second:?}, so it is not measuring from the \
476 origin the first call installed"
477 );
478 reset_stderr_deadline_origin_for_test();
479 }
480
481 /// Which bound is in force must be answerable, not assumed.
482 #[test]
483 fn whether_the_deadline_is_invocation_wide_is_observable() {
484 let _exclusive = exclusive();
485 init_shared_stderr_deadline_origin();
486 // ⚠️ THE WEAKER STATE MUST NOT BE SILENT. If the mapping failed, or something
487 // forks before the init call, the deadline degrades to per-process and is
488 // multiplied by however many processes write.
489 assert!(
490 stderr_deadline_is_shared(),
491 "the origin is not shared after init, so the deadline is per-process and \
492 is multiplied by the number of writing processes"
493 );
494 }
495}