Skip to main content

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}