par_term/debug.rs
1/// Comprehensive debugging infrastructure for par-term
2///
3/// # Dual Logging Systems (ARC-008)
4///
5/// par-term intentionally runs **two parallel logging systems** that both funnel into the
6/// same log file. This coexistence is by design, not accident:
7///
8/// 1. **Custom debug macros** (`crate::debug_info!()`, `crate::debug_log!()`, etc.)
9/// - Controlled by `DEBUG_LEVEL` environment variable (0-4)
10/// - Best for high-frequency rendering/input logging with category tags
11/// - Categories (e.g., `"RENDER"`, `"TAB"`, `"SHADER"`) allow selective filtering
12/// - Zero overhead when `DEBUG_LEVEL=0` (the default)
13///
14/// 2. **Standard `log` crate** (`log::info!()`, `log::warn!()`, etc.)
15/// - Controlled by `RUST_LOG` environment variable
16/// - Used by application lifecycle code (startup, config load, errors)
17/// - Required for third-party crates (wgpu, tokio, etc.) that emit via `log`
18///
19/// ## Why Both Systems Coexist
20///
21/// The custom macros predate widespread `tracing` adoption and were purpose-built for
22/// GPU-loop debugging where `RUST_LOG=debug` would produce millions of lines per second.
23/// The category/level system lets a developer write `DEBUG_LEVEL=3` and see only
24/// rendering events without drowning in tokio internals.
25///
26/// The `log` crate is kept because third-party dependencies (wgpu, tokio, egui) emit
27/// through it exclusively, and because lifecycle events (startup, config) benefit from
28/// the standard `env_logger`/`RUST_LOG` filtering UX.
29///
30/// ## Migration Path (TODO ARC-008)
31///
32/// Long-term, both systems should be unified under `tracing` (the modern Rust async-aware
33/// tracing framework). Migration path:
34/// 1. Replace `crate::debug_info!()` macros with `tracing::trace!(category = "RENDER", ...)`
35/// 2. Replace `log::info!()` calls with `tracing::info!()`
36/// 3. Bridge `log` crate output to tracing with `tracing_log::LogTracer`
37/// 4. Use `tracing_subscriber` with `EnvFilter` for unified level/category control
38/// 5. Keep the file sink; replace the custom `DebugLogger` with a tracing file appender
39///
40/// This is a non-trivial migration touching ~500 call sites. Do not attempt without
41/// a dedicated effort. Until then, the dual system is the accepted state.
42///
43/// Both write to `<temp_dir>/par_term_debug.log` (respects `$TMPDIR` on Unix, `%TEMP%` on Windows).
44/// The log file is always created so that errors are captured even in GUI-only contexts
45/// (macOS app bundles, Windows GUI apps) where stderr is invisible.
46/// The log file is created with 0600 permissions on Unix (set at creation, not chmod'ed
47/// afterwards) and symlink-checked to prevent attacks. If the path already exists and is
48/// owned by another user, logging is disabled rather than writing where they can read it.
49///
50/// When `RUST_LOG` is set, `log` crate output is also mirrored to stderr for terminal debugging.
51use parking_lot::Mutex;
52use std::fmt;
53use std::fs::OpenOptions;
54use std::io::Write;
55use std::sync::OnceLock;
56use std::time::{SystemTime, UNIX_EPOCH};
57
58/// Debug level configuration for custom debug macros
59#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)]
60pub enum DebugLevel {
61 Off = 0,
62 Error = 1,
63 Info = 2,
64 Debug = 3,
65 Trace = 4,
66}
67
68impl DebugLevel {
69 fn from_env() -> Self {
70 match std::env::var("DEBUG_LEVEL") {
71 Ok(val) => match val.trim().parse::<u8>() {
72 Ok(0) => DebugLevel::Off,
73 Ok(1) => DebugLevel::Error,
74 Ok(2) => DebugLevel::Info,
75 Ok(3) => DebugLevel::Debug,
76 Ok(4) => DebugLevel::Trace,
77 _ => DebugLevel::Off,
78 },
79 Err(_) => DebugLevel::Off,
80 }
81 }
82}
83
84/// Global debug logger that handles both custom debug macros and `log` crate output.
85struct DebugLogger {
86 /// Level for custom debug macros (controlled by DEBUG_LEVEL)
87 level: DebugLevel,
88 /// Log file handle (always opened)
89 file: Option<std::fs::File>,
90 /// Mirror custom debug macros to stderr (true when `RUST_LOG` is set), so
91 /// `make run-debug` (which tees stderr to the log file) captures them live.
92 mirror_stderr: bool,
93}
94
95/// Roll the previous session's log aside to `<log>.1`.
96///
97/// The log is opened with `truncate(true)`, so without this the crash report the
98/// panic hook writes (see `src/session/crash_guard.rs`) is erased by the next
99/// launch — which, after a crash, is usually seconds later.
100///
101/// Rename rather than copy: it is atomic, needs no read of a log that may be
102/// large, and leaves the `.1` file with the 0600 mode it was created under.
103/// Only one generation is kept; a log worth more than that belongs in a tee.
104///
105/// Skipped, leaving any existing `.1` intact, when the log is
106///
107/// - absent, or empty — `make run-debug` pipes through `tee`, which truncates
108/// the path before par-term starts, so rotating there would clobber a real
109/// previous log with nothing;
110/// - not a regular file — a symlink is unlinked by [`open_log_file`] first, and
111/// anything else is not ours to move;
112/// - owned by another user — [`open_log_file`] refuses to write such a path
113/// (SEC-016), and renaming it away would quietly convert that refusal into
114/// "log anyway, into a fresh file".
115fn rotate_log_file(log_path: &std::path::Path) {
116 let Ok(meta) = log_path.symlink_metadata() else {
117 return;
118 };
119 if !meta.is_file() || meta.len() == 0 {
120 return;
121 }
122
123 #[cfg(unix)]
124 {
125 use std::os::unix::fs::MetadataExt;
126 // SAFETY: `getuid` has no preconditions, takes no arguments and always
127 // succeeds.
128 if meta.uid() != unsafe { libc::getuid() } {
129 return;
130 }
131 }
132
133 let mut rolled = log_path.as_os_str().to_owned();
134 rolled.push(".1");
135 let _ = std::fs::rename(log_path, std::path::PathBuf::from(rolled));
136}
137
138/// Open (creating or truncating) the debug log with owner-only permissions.
139///
140/// The previous session's log is first rolled aside by [`rotate_log_file`], so
141/// truncation here costs the log of the run before last, not the last one.
142///
143/// Returns `None` — disabling file logging rather than leaking — when the path
144/// cannot be opened safely.
145///
146/// SEC-010: any existing symlink is unlinked first, and on Unix `O_NOFOLLOW` closes
147/// the TOCTOU race between that unlink and the open. On non-Unix platforms the
148/// check-then-open approach is the only available option.
149///
150/// SEC-016: 0600 is requested as the *creation* mode rather than chmod'ed after the
151/// open. A post-open chmod leaves the file world-readable for the length of the
152/// write window and, in the case that actually matters, fails outright — silently —
153/// when the path was pre-created by someone else, because chmod requires ownership.
154/// `temp_dir()` is `/tmp` on Linux: shared and world-writable.
155fn open_log_file(log_path: &std::path::Path) -> Option<std::fs::File> {
156 if log_path
157 .symlink_metadata()
158 .map(|m| m.file_type().is_symlink())
159 .unwrap_or(false)
160 {
161 let _ = std::fs::remove_file(log_path);
162 }
163
164 rotate_log_file(log_path);
165
166 #[cfg(unix)]
167 {
168 use std::os::unix::fs::{MetadataExt, OpenOptionsExt};
169 // O_NOFOLLOW (0x20000 on Linux / 0x100 on macOS) causes open() to fail with
170 // ELOOP if the final path component is a symlink, regardless of who created it.
171 OpenOptions::new()
172 .write(true)
173 .truncate(true)
174 .create(true)
175 .mode(0o600)
176 .custom_flags(libc::O_NOFOLLOW)
177 .open(log_path)
178 .ok()
179 .filter(|f| {
180 // The creation mode above only applies to a file *this* process
181 // creates. If the path was pre-created mode 0666 by another user, the
182 // open still succeeds and they keep read access to everything written
183 // here, so refuse to log rather than leak. Checked on the open
184 // descriptor, so there is no TOCTOU window.
185 // SAFETY: `getuid` has no preconditions, takes no arguments and
186 // always succeeds.
187 let our_uid = unsafe { libc::getuid() };
188 match f.metadata() {
189 Ok(meta) if meta.uid() == our_uid => true,
190 Ok(meta) => {
191 eprintln!(
192 "par-term: refusing to write {} — it is owned by uid {}, not \
193 this user. Debug file logging is disabled.",
194 log_path.display(),
195 meta.uid()
196 );
197 false
198 }
199 Err(_) => false,
200 }
201 })
202 }
203
204 #[cfg(not(unix))]
205 {
206 OpenOptions::new()
207 .write(true)
208 .truncate(true)
209 .create(true)
210 .open(log_path)
211 .ok()
212 }
213}
214
215impl DebugLogger {
216 fn new() -> Self {
217 let level = DebugLevel::from_env();
218
219 let file = open_log_file(&log_path());
220
221 let mirror_stderr = std::env::var("RUST_LOG").is_ok();
222 let mut logger = DebugLogger {
223 level,
224 file,
225 mirror_stderr,
226 };
227 logger.write_raw(&format!(
228 "\n{}\npar-term log session started at {} (debug_level={:?}, rust_log={})\n{}\n",
229 "=".repeat(80),
230 get_timestamp(),
231 level,
232 std::env::var("RUST_LOG").unwrap_or_else(|_| "unset".to_string()),
233 "=".repeat(80)
234 ));
235 logger
236 }
237
238 fn write_raw(&mut self, msg: &str) {
239 if let Some(ref mut file) = self.file {
240 let _ = file.write_all(msg.as_bytes());
241 let _ = file.flush();
242 }
243 }
244
245 /// Write a custom debug macro message (respects DEBUG_LEVEL)
246 fn log(&mut self, level: DebugLevel, category: &str, msg: &str) {
247 if level <= self.level {
248 let timestamp = get_timestamp();
249 let level_str = match level {
250 DebugLevel::Error => "ERROR",
251 DebugLevel::Info => "INFO ",
252 DebugLevel::Debug => "DEBUG",
253 DebugLevel::Trace => "TRACE",
254 DebugLevel::Off => return,
255 };
256 self.write_raw(&format!(
257 "[{}] [{}] [{}] {}\n",
258 timestamp, level_str, category, msg
259 ));
260 // Mirror to stderr during debug runs (RUST_LOG set), so `make run-debug`
261 // — which tees stderr to the log file — captures custom-macro output too.
262 if self.mirror_stderr {
263 eprintln!("[{}] {}: {}", level_str.trim_end(), category, msg);
264 }
265 }
266 }
267
268 /// Write a `log` crate record (always writes to file)
269 fn log_record(&mut self, record: &log::Record) {
270 let timestamp = get_timestamp();
271 let level_str = match record.level() {
272 log::Level::Error => "ERROR",
273 log::Level::Warn => "WARN ",
274 log::Level::Info => "INFO ",
275 log::Level::Debug => "DEBUG",
276 log::Level::Trace => "TRACE",
277 };
278 self.write_raw(&format!(
279 "[{}] [{}] [{}] {}\n",
280 timestamp,
281 level_str,
282 record.target(),
283 record.args()
284 ));
285 }
286}
287
288static LOGGER: OnceLock<Mutex<DebugLogger>> = OnceLock::new();
289
290fn get_logger() -> &'static Mutex<DebugLogger> {
291 LOGGER.get_or_init(|| Mutex::new(DebugLogger::new()))
292}
293
294fn get_timestamp() -> String {
295 let now = SystemTime::now()
296 .duration_since(UNIX_EPOCH)
297 .expect("SystemTime::now() is always after UNIX_EPOCH");
298 format!("{}.{:06}", now.as_secs(), now.subsec_micros())
299}
300
301/// Get the path to the debug log file.
302pub fn log_path() -> std::path::PathBuf {
303 std::env::temp_dir().join("par_term_debug.log")
304}
305
306/// Check if debugging is enabled at given level (for custom debug macros)
307pub fn is_enabled(level: DebugLevel) -> bool {
308 let logger = get_logger().lock();
309 level <= logger.level
310}
311
312/// Log a message at specified level (for custom debug macros)
313pub fn log(level: DebugLevel, category: &str, msg: &str) {
314 let mut logger = get_logger().lock();
315 logger.log(level, category, msg);
316}
317
318/// Log formatted message (for custom debug macros)
319pub fn logf(level: DebugLevel, category: &str, args: fmt::Arguments) {
320 if is_enabled(level) {
321 log(level, category, &format!("{}", args));
322 }
323}
324
325/// Write one line to the debug log without ever blocking. Returns whether it
326/// was written.
327///
328/// Every other entry point takes the logger mutex unconditionally, and
329/// `parking_lot::Mutex` is not reentrant: a panic raised while that lock is held
330/// hangs any hook that then tries to log — the failure mode documented in
331/// `src/session/crash_guard.rs`. This drops the line instead of hanging. It also
332/// never initializes the logger, because re-entering `OnceLock::get_or_init` on
333/// the same thread is its own deadlock.
334///
335/// Two deliberate differences from [`logf`]:
336///
337/// - `DEBUG_LEVEL` does not filter the message. The callers this exists for are
338/// reporting a fault, not tracing, and at the default `DEBUG_LEVEL=0` a
339/// filtered write would produce nothing at all.
340/// - Nothing is mirrored to stderr. A panic hook's stderr output is already
341/// written by the default hook it chains to.
342pub fn try_logf(level: DebugLevel, category: &str, args: fmt::Arguments) -> bool {
343 let level_str = match level {
344 DebugLevel::Error => "ERROR",
345 DebugLevel::Info => "INFO ",
346 DebugLevel::Debug => "DEBUG",
347 DebugLevel::Trace => "TRACE",
348 DebugLevel::Off => return false,
349 };
350 let Some(logger) = LOGGER.get() else {
351 return false;
352 };
353 let Some(mut logger) = logger.try_lock() else {
354 return false;
355 };
356 logger.write_raw(&format!(
357 "[{}] [{}] [{}] {}\n",
358 get_timestamp(),
359 level_str,
360 category,
361 args
362 ));
363 true
364}
365
366// ============================================================================
367// log crate bridge — routes log::info!() etc. to the debug log file
368// ============================================================================
369
370/// Bridge that implements the `log` crate's `Log` trait, routing all log
371/// output to the par-term debug log file. Optionally mirrors to stderr
372/// when `RUST_LOG` is set (for terminal debugging).
373struct LogCrateBridge {
374 /// Maximum level to accept (parsed from RUST_LOG, default: Info)
375 max_level: log::LevelFilter,
376 /// Whether to also write to stderr (true when RUST_LOG is explicitly set)
377 mirror_stderr: bool,
378 /// Module-level filters (module_prefix, max_level) for noisy crates
379 module_filters: Vec<(&'static str, log::LevelFilter)>,
380}
381
382impl LogCrateBridge {
383 fn new() -> Self {
384 let rust_log_set = std::env::var("RUST_LOG").is_ok();
385 let max_level = if rust_log_set {
386 // Parse RUST_LOG for the default level (simplified: just use the first token)
387 match std::env::var("RUST_LOG")
388 .unwrap_or_default()
389 .to_lowercase()
390 .as_str()
391 {
392 "trace" => log::LevelFilter::Trace,
393 "debug" => log::LevelFilter::Debug,
394 "info" => log::LevelFilter::Info,
395 "warn" => log::LevelFilter::Warn,
396 "error" => log::LevelFilter::Error,
397 "off" => log::LevelFilter::Off,
398 _ => log::LevelFilter::Info, // default if RUST_LOG has module-specific syntax
399 }
400 } else {
401 // No RUST_LOG: capture info and above to the log file
402 log::LevelFilter::Info
403 };
404
405 LogCrateBridge {
406 max_level,
407 mirror_stderr: rust_log_set,
408 module_filters: vec![
409 ("wgpu_core", log::LevelFilter::Warn),
410 ("wgpu_hal", log::LevelFilter::Warn),
411 ("naga", log::LevelFilter::Warn),
412 ("rodio", log::LevelFilter::Error),
413 ("cpal", log::LevelFilter::Error),
414 ],
415 }
416 }
417
418 fn level_for_module(&self, target: &str) -> log::LevelFilter {
419 for (prefix, filter) in &self.module_filters {
420 if target.starts_with(prefix) {
421 return *filter;
422 }
423 }
424 self.max_level
425 }
426}
427
428impl log::Log for LogCrateBridge {
429 fn enabled(&self, metadata: &log::Metadata) -> bool {
430 metadata.level() <= self.level_for_module(metadata.target())
431 }
432
433 fn log(&self, record: &log::Record) {
434 if !self.enabled(record.metadata()) {
435 return;
436 }
437
438 // Write to the debug log file
439 let mut logger = get_logger().lock();
440 logger.log_record(record);
441 drop(logger);
442
443 // Mirror to stderr when RUST_LOG is set (for terminal debugging)
444 if self.mirror_stderr {
445 eprintln!(
446 "[{}] {}: {}",
447 record.level(),
448 record.target(),
449 record.args()
450 );
451 }
452 }
453
454 fn flush(&self) {}
455}
456
457/// Initialize the `log` crate bridge. Call this once from main() instead of env_logger::init().
458/// Routes all `log::info!()` etc. calls to the par-term debug log file.
459/// When `RUST_LOG` is set, also mirrors to stderr for terminal debugging.
460///
461/// `level_override` allows CLI or config to set the level. If `None`, uses
462/// `RUST_LOG` env var (or defaults to `Info`).
463pub fn init_log_bridge(level_override: Option<log::LevelFilter>) {
464 // Force logger initialization (opens the log file)
465 let _ = get_logger();
466
467 let bridge = LogCrateBridge::new();
468 // CLI/config override takes precedence, then RUST_LOG, then default
469 let max_level = level_override.unwrap_or(bridge.max_level);
470
471 // Install as the global logger
472 if log::set_boxed_logger(Box::new(bridge)).is_ok() {
473 log::set_max_level(max_level);
474 }
475}
476
477/// Update the log level at runtime (e.g., from settings UI).
478/// This only changes `log::max_level()` — the bridge itself always writes
479/// whatever passes the filter.
480pub fn set_log_level(level: log::LevelFilter) {
481 log::set_max_level(level);
482}
483
484// ============================================================================
485// try_lock failure telemetry
486// ============================================================================
487
488/// Total number of `try_lock()` calls that returned `Err` (lock contended) across all
489/// call sites in the application. Incremented via [`record_try_lock_failure`].
490///
491/// Deliberately a module-level static so it is zero-cost when the counter is never
492/// read — the increment itself is a single `fetch_add(Relaxed)`.
493pub static TRY_LOCK_FAILURE_COUNT: std::sync::atomic::AtomicU64 =
494 std::sync::atomic::AtomicU64::new(0);
495
496/// The value of [`TRY_LOCK_FAILURE_COUNT`] at the time of the last periodic telemetry
497/// log. Used by [`maybe_log_try_lock_telemetry`] to avoid emitting redundant log lines.
498static TRY_LOCK_LAST_REPORTED: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0);
499
500/// Record one `try_lock()` failure.
501///
502/// Increments [`TRY_LOCK_FAILURE_COUNT`] and emits a `CONCURRENCY` debug-log entry
503/// (visible at `DEBUG_LEVEL >= 3`).
504///
505/// # Arguments
506/// * `site` - A short, human-readable label identifying the call site
507/// (e.g., `"resize"`, `"theme_change"`, `"focus_event"`).
508#[inline]
509pub fn record_try_lock_failure(site: &str) {
510 let total = TRY_LOCK_FAILURE_COUNT.fetch_add(1, std::sync::atomic::Ordering::Relaxed) + 1;
511 logf(
512 DebugLevel::Debug,
513 "CONCURRENCY",
514 format_args!("try_lock() miss at '{}' (lifetime total: {})", site, total),
515 );
516}
517
518/// Return the current lifetime total of `try_lock()` failures.
519///
520/// Intended for periodic telemetry reporting (e.g., once per second in
521/// `about_to_wait` in `crate::app::handler::window_state_impl`).
522#[inline]
523pub fn try_lock_failure_count() -> u64 {
524 TRY_LOCK_FAILURE_COUNT.load(std::sync::atomic::Ordering::Relaxed)
525}
526
527/// Emit a periodic telemetry summary if new `try_lock()` failures have been recorded
528/// since the last call.
529///
530/// This is designed to be called from `about_to_wait` (once per event-loop iteration)
531/// so that lock-contention pressure is surfaced in the debug log without generating
532/// per-failure log spam at higher rates. The log entry is only written when at least
533/// one new failure occurred since the previous call.
534pub fn maybe_log_try_lock_telemetry() {
535 let current = TRY_LOCK_FAILURE_COUNT.load(std::sync::atomic::Ordering::Relaxed);
536 let last = TRY_LOCK_LAST_REPORTED.load(std::sync::atomic::Ordering::Relaxed);
537 if current > last {
538 // Use compare_exchange to ensure only one caller logs when there are
539 // multiple windows. The "loser" simply skips this cycle.
540 if TRY_LOCK_LAST_REPORTED
541 .compare_exchange(
542 last,
543 current,
544 std::sync::atomic::Ordering::Relaxed,
545 std::sync::atomic::Ordering::Relaxed,
546 )
547 .is_ok()
548 {
549 let new_since_last = current - last;
550 logf(
551 DebugLevel::Info,
552 "CONCURRENCY",
553 format_args!(
554 "try_lock telemetry: {} new failure(s) this interval, {} lifetime total",
555 new_since_last, current
556 ),
557 );
558 }
559 }
560}
561
562// ============================================================================
563// Custom debug macros (unchanged, controlled by DEBUG_LEVEL)
564// ============================================================================
565
566#[macro_export]
567macro_rules! debug_error {
568 ($category:expr, $($arg:tt)*) => {
569 $crate::debug::logf($crate::debug::DebugLevel::Error, $category, format_args!($($arg)*))
570 };
571}
572
573#[macro_export]
574macro_rules! debug_info {
575 ($category:expr, $($arg:tt)*) => {
576 $crate::debug::logf($crate::debug::DebugLevel::Info, $category, format_args!($($arg)*))
577 };
578}
579
580#[macro_export]
581macro_rules! debug_log {
582 ($category:expr, $($arg:tt)*) => {
583 $crate::debug::logf($crate::debug::DebugLevel::Debug, $category, format_args!($($arg)*))
584 };
585}
586
587#[macro_export]
588macro_rules! debug_trace {
589 ($category:expr, $($arg:tt)*) => {
590 $crate::debug::logf($crate::debug::DebugLevel::Trace, $category, format_args!($($arg)*))
591 };
592}
593
594// ============================================================================
595// Combined debug-log macros (R-18)
596//
597// Several call sites emit both a `crate::debug_error!` (routed to the custom
598// debug log file, controlled by DEBUG_LEVEL) AND a `log::warn!` / `log::error!`
599// (routed through the standard `log` crate bridge, controlled by RUST_LOG).
600//
601// These two-line patterns are collapsed into a single `debug_and_log!` call:
602//
603// debug_and_log!(WARN, "CATEGORY", "message {}", var);
604// debug_and_log!(ERROR, "CATEGORY", "message {}", var);
605//
606// The macro writes to the custom debug log at the `Error` level **and** emits
607// the same message through `log::warn!` or `log::error!` respectively.
608// ============================================================================
609
610/// Emit a message to both the custom debug log (at `Error` level) and the
611/// standard `log` crate at `log::warn!` level.
612///
613/// # Example
614/// ```ignore
615/// debug_and_log!(WARN, "TMUX", "Failed to attach session '{}': {}", name, e);
616/// ```
617#[macro_export]
618macro_rules! debug_and_log_warn {
619 ($category:expr, $($arg:tt)*) => {{
620 $crate::debug::logf(
621 $crate::debug::DebugLevel::Error,
622 $category,
623 format_args!($($arg)*),
624 );
625 log::warn!($($arg)*);
626 }};
627}
628
629/// Emit a message to both the custom debug log (at `Error` level) and the
630/// standard `log` crate at `log::error!` level.
631///
632/// # Example
633/// ```ignore
634/// debug_and_log_error!("SCRIPT", "Script '{}' failed: {}", name, e);
635/// ```
636#[macro_export]
637macro_rules! debug_and_log_error {
638 ($category:expr, $($arg:tt)*) => {{
639 $crate::debug::logf(
640 $crate::debug::DebugLevel::Error,
641 $category,
642 format_args!($($arg)*),
643 );
644 log::error!($($arg)*);
645 }};
646}
647
648#[cfg(test)]
649mod tests {
650 use super::*;
651
652 /// SEC-016: the log must be owner-only from the moment it is created. A chmod
653 /// after the open leaves a world-readable window and fails silently when the
654 /// path was pre-created by another user.
655 #[cfg(unix)]
656 #[test]
657 fn log_file_is_created_owner_only() {
658 use std::os::unix::fs::PermissionsExt;
659
660 let dir = tempfile::tempdir().expect("temp dir");
661 let path = dir.path().join("par_term_debug.log");
662
663 let file = open_log_file(&path).expect("log file opens");
664 drop(file);
665
666 let mode = std::fs::metadata(&path)
667 .expect("log file created")
668 .permissions()
669 .mode();
670 assert_eq!(
671 mode & 0o777,
672 0o600,
673 "debug log must not be group/world readable"
674 );
675 }
676
677 /// SEC-010 regression: a symlink planted at the log path must not be written
678 /// through, whoever owns it.
679 #[cfg(unix)]
680 #[test]
681 fn log_file_open_does_not_follow_a_planted_symlink() {
682 let dir = tempfile::tempdir().expect("temp dir");
683 let path = dir.path().join("par_term_debug.log");
684 let target = dir.path().join("victim");
685
686 std::fs::write(&target, "original").expect("seed symlink target");
687 std::os::unix::fs::symlink(&target, &path).expect("plant symlink");
688
689 let mut file = open_log_file(&path).expect("log file opens");
690 std::io::Write::write_all(&mut file, b"leaked").expect("write");
691 drop(file);
692
693 assert_eq!(
694 std::fs::read_to_string(&target).expect("read target"),
695 "original",
696 "the log must not be written through the planted symlink"
697 );
698 }
699
700 #[test]
701 fn log_file_is_truncated_on_reopen() {
702 let dir = tempfile::tempdir().expect("temp dir");
703 let path = dir.path().join("par_term_debug.log");
704
705 std::fs::write(&path, "stale session output").expect("seed log");
706
707 let file = open_log_file(&path).expect("log file opens");
708 drop(file);
709
710 assert_eq!(std::fs::read_to_string(&path).expect("read log"), "");
711 }
712
713 /// The previous session's log — which after a crash holds the panic report —
714 /// must survive the next launch's truncation.
715 #[test]
716 fn previous_log_is_rolled_aside_on_reopen() {
717 let dir = tempfile::tempdir().expect("temp dir");
718 let path = dir.path().join("par_term_debug.log");
719 let rolled = dir.path().join("par_term_debug.log.1");
720
721 std::fs::write(&path, "PANIC report from the run that crashed").expect("seed log");
722
723 let file = open_log_file(&path).expect("log file opens");
724 drop(file);
725
726 assert_eq!(
727 std::fs::read_to_string(&rolled).expect("previous log rolled aside"),
728 "PANIC report from the run that crashed"
729 );
730 }
731
732 /// `make run-debug` pipes through `tee`, which truncates the log before
733 /// par-term opens it. Rotating an empty log there would replace a real
734 /// previous log with nothing.
735 #[test]
736 fn an_empty_log_is_not_rotated() {
737 let dir = tempfile::tempdir().expect("temp dir");
738 let path = dir.path().join("par_term_debug.log");
739 let rolled = dir.path().join("par_term_debug.log.1");
740
741 std::fs::write(&rolled, "the log worth keeping").expect("seed rolled log");
742 std::fs::write(&path, "").expect("seed empty log");
743
744 let file = open_log_file(&path).expect("log file opens");
745 drop(file);
746
747 assert_eq!(
748 std::fs::read_to_string(&rolled).expect("read rolled log"),
749 "the log worth keeping",
750 "an empty log must not overwrite the previous rotation"
751 );
752 }
753
754 /// The panic hook's requirement: report a fault without taking the logger
755 /// mutex, and without being filtered out at the default `DEBUG_LEVEL=0`.
756 #[test]
757 fn try_logf_neither_blocks_nor_initializes_the_logger() {
758 // Only one direction is assertable, and both of the tempting stronger
759 // claims are wrong under `cargo test`'s default parallelism. `LOGGER` is
760 // a `OnceLock`, so a concurrent test can install it between the call and
761 // a later reading. And an installed logger does *not* imply a write:
762 // `try_logf` uses `try_lock` and drops the line when another thread
763 // holds the mutex, which is the whole reason it exists for the panic
764 // hook. So: a write implies a logger, and nothing else.
765 let wrote = try_logf(DebugLevel::Error, "TEST", format_args!("no deadlock"));
766 assert!(
767 !wrote || LOGGER.get().is_some(),
768 "try_logf reported a write with no logger installed"
769 );
770
771 assert!(
772 !try_logf(DebugLevel::Off, "TEST", format_args!("ignored")),
773 "DebugLevel::Off has no line format and must never be written"
774 );
775
776 // Held lock: the panic-hook case. Must return false, not hang.
777 if let Some(logger) = LOGGER.get() {
778 let held = logger.lock();
779 assert!(
780 !try_logf(DebugLevel::Error, "TEST", format_args!("contended")),
781 "try_logf must drop the line while the logger mutex is held"
782 );
783 drop(held);
784 }
785 }
786
787 /// The hazard [`try_logf`] exists to remove, exercised through the caller it
788 /// was wired into: the panic hook's report step must return while the logger
789 /// mutex is held rather than deadlocking on it.
790 ///
791 /// Driven through `crash_guard::report_fields` — the report path with the
792 /// `PanicHookInfo` destructuring lifted off — rather than a real panic. A
793 /// real one is not reproducible from a test: the hook is process-global and
794 /// latched, it binds to whichever thread installs it first, libtest installs
795 /// a hook of its own, and `PanicHookInfo` cannot be constructed.
796 ///
797 /// The contended half only bites once some earlier test has initialized
798 /// `LOGGER`, and nothing here forces that, because initializing it rotates
799 /// and truncates the developer's real debug log. The watchdog turns a
800 /// reintroduced blocking call — a `log::error!` in that path reaches this
801 /// same mutex through [`LogCrateBridge`] — into a failure rather than a run
802 /// that hangs forever.
803 #[test]
804 fn the_panic_report_never_blocks_on_the_logger() {
805 use crate::session::crash_guard::{PanicReport, SaveOutcome, report_fields};
806
807 fn fields(outcome: Option<SaveOutcome>) -> PanicReport<'static> {
808 PanicReport {
809 thread_name: "test",
810 file: "src/debug.rs",
811 line: 1,
812 column: 1,
813 payload: "provoked",
814 outcome,
815 }
816 }
817
818 // Uncontended: every outcome the hook can report runs to completion.
819 // The hook must stay infallible whichever branch it takes.
820 for outcome in [
821 None,
822 Some(SaveOutcome::Saved),
823 Some(SaveOutcome::NoSnapshot),
824 Some(SaveOutcome::AlreadySaved),
825 Some(SaveOutcome::WriteFailed),
826 ] {
827 report_fields(fields(outcome));
828 }
829
830 let Some(logger) = LOGGER.get() else {
831 return;
832 };
833 let held = logger.lock();
834
835 let (tx, rx) = std::sync::mpsc::channel();
836 std::thread::spawn(move || {
837 report_fields(fields(Some(SaveOutcome::Saved)));
838 let _ = tx.send(());
839 });
840 let finished = rx.recv_timeout(std::time::Duration::from_secs(10)).is_ok();
841 drop(held);
842
843 assert!(
844 finished,
845 "the panic hook's report step blocked on the logger mutex"
846 );
847 }
848}