par-term 0.30.10

/// Comprehensive debugging infrastructure for par-term
///
/// # Dual Logging Systems (ARC-008)
///
/// par-term intentionally runs **two parallel logging systems** that both funnel into the
/// same log file. This coexistence is by design, not accident:
///
/// 1. **Custom debug macros** (`crate::debug_info!()`, `crate::debug_log!()`, etc.)
///    - Controlled by `DEBUG_LEVEL` environment variable (0-4)
///    - Best for high-frequency rendering/input logging with category tags
///    - Categories (e.g., `"RENDER"`, `"TAB"`, `"SHADER"`) allow selective filtering
///    - Zero overhead when `DEBUG_LEVEL=0` (the default)
///
/// 2. **Standard `log` crate** (`log::info!()`, `log::warn!()`, etc.)
///    - Controlled by `RUST_LOG` environment variable
///    - Used by application lifecycle code (startup, config load, errors)
///    - Required for third-party crates (wgpu, tokio, etc.) that emit via `log`
///
/// ## Why Both Systems Coexist
///
/// The custom macros predate widespread `tracing` adoption and were purpose-built for
/// GPU-loop debugging where `RUST_LOG=debug` would produce millions of lines per second.
/// The category/level system lets a developer write `DEBUG_LEVEL=3` and see only
/// rendering events without drowning in tokio internals.
///
/// The `log` crate is kept because third-party dependencies (wgpu, tokio, egui) emit
/// through it exclusively, and because lifecycle events (startup, config) benefit from
/// the standard `env_logger`/`RUST_LOG` filtering UX.
///
/// ## Migration Path (TODO ARC-008)
///
/// Long-term, both systems should be unified under `tracing` (the modern Rust async-aware
/// tracing framework). Migration path:
///   1. Replace `crate::debug_info!()` macros with `tracing::trace!(category = "RENDER", ...)`
///   2. Replace `log::info!()` calls with `tracing::info!()`
///   3. Bridge `log` crate output to tracing with `tracing_log::LogTracer`
///   4. Use `tracing_subscriber` with `EnvFilter` for unified level/category control
///   5. Keep the file sink; replace the custom `DebugLogger` with a tracing file appender
///
/// This is a non-trivial migration touching ~500 call sites. Do not attempt without
/// a dedicated effort. Until then, the dual system is the accepted state.
///
/// Both write to `<temp_dir>/par_term_debug.log` (respects `$TMPDIR` on Unix, `%TEMP%` on Windows).
/// The log file is always created so that errors are captured even in GUI-only contexts
/// (macOS app bundles, Windows GUI apps) where stderr is invisible.
/// The log file is created with 0600 permissions on Unix and symlink-checked to prevent attacks.
///
/// When `RUST_LOG` is set, `log` crate output is also mirrored to stderr for terminal debugging.
use parking_lot::Mutex;
use std::fmt;
use std::fs::OpenOptions;
use std::io::Write;
use std::sync::OnceLock;
use std::time::{SystemTime, UNIX_EPOCH};

/// Debug level configuration for custom debug macros
#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)]
pub enum DebugLevel {
    Off = 0,
    Error = 1,
    Info = 2,
    Debug = 3,
    Trace = 4,
}

impl DebugLevel {
    fn from_env() -> Self {
        match std::env::var("DEBUG_LEVEL") {
            Ok(val) => match val.trim().parse::<u8>() {
                Ok(0) => DebugLevel::Off,
                Ok(1) => DebugLevel::Error,
                Ok(2) => DebugLevel::Info,
                Ok(3) => DebugLevel::Debug,
                Ok(4) => DebugLevel::Trace,
                _ => DebugLevel::Off,
            },
            Err(_) => DebugLevel::Off,
        }
    }
}

/// Global debug logger that handles both custom debug macros and `log` crate output.
struct DebugLogger {
    /// Level for custom debug macros (controlled by DEBUG_LEVEL)
    level: DebugLevel,
    /// Log file handle (always opened)
    file: Option<std::fs::File>,
}

impl DebugLogger {
    fn new() -> Self {
        let level = DebugLevel::from_env();

        let log_path = std::env::temp_dir().join("par_term_debug.log");

        // Security: refuse to open symlinks (prevents symlink attacks).
        // Remove any existing symlink before opening; O_NOFOLLOW (Unix-only, below) closes
        // the TOCTOU race between this removal and the open call.
        if log_path
            .symlink_metadata()
            .map(|m| m.file_type().is_symlink())
            .unwrap_or(false)
        {
            let _ = std::fs::remove_file(&log_path);
        }

        // SEC-010: Use O_NOFOLLOW on Unix to atomically reject symlinks at open time,
        // eliminating the TOCTOU race between the symlink check above and this open call.
        // On non-Unix platforms the check-then-open approach is the only available option.
        #[cfg(unix)]
        let file = {
            use std::os::unix::fs::OpenOptionsExt;
            // O_NOFOLLOW (0x20000 on Linux / 0x100 on macOS) causes open() to fail with
            // ELOOP if the final path component is a symlink, regardless of who created it.
            OpenOptions::new()
                .write(true)
                .truncate(true)
                .create(true)
                .custom_flags(libc::O_NOFOLLOW)
                .open(&log_path)
                .ok()
        };

        #[cfg(not(unix))]
        let file = OpenOptions::new()
            .write(true)
            .truncate(true)
            .create(true)
            .open(&log_path)
            .ok();

        // Security: restrict log file to owner-only access on Unix
        #[cfg(unix)]
        if file.is_some() {
            use std::os::unix::fs::PermissionsExt;
            let _ = std::fs::set_permissions(&log_path, std::fs::Permissions::from_mode(0o600));
        }

        let mut logger = DebugLogger { level, file };
        logger.write_raw(&format!(
            "\n{}\npar-term log session started at {} (debug_level={:?}, rust_log={})\n{}\n",
            "=".repeat(80),
            get_timestamp(),
            level,
            std::env::var("RUST_LOG").unwrap_or_else(|_| "unset".to_string()),
            "=".repeat(80)
        ));
        logger
    }

    fn write_raw(&mut self, msg: &str) {
        if let Some(ref mut file) = self.file {
            let _ = file.write_all(msg.as_bytes());
            let _ = file.flush();
        }
    }

    /// Write a custom debug macro message (respects DEBUG_LEVEL)
    fn log(&mut self, level: DebugLevel, category: &str, msg: &str) {
        if level <= self.level {
            let timestamp = get_timestamp();
            let level_str = match level {
                DebugLevel::Error => "ERROR",
                DebugLevel::Info => "INFO ",
                DebugLevel::Debug => "DEBUG",
                DebugLevel::Trace => "TRACE",
                DebugLevel::Off => return,
            };
            self.write_raw(&format!(
                "[{}] [{}] [{}] {}\n",
                timestamp, level_str, category, msg
            ));
        }
    }

    /// Write a `log` crate record (always writes to file)
    fn log_record(&mut self, record: &log::Record) {
        let timestamp = get_timestamp();
        let level_str = match record.level() {
            log::Level::Error => "ERROR",
            log::Level::Warn => "WARN ",
            log::Level::Info => "INFO ",
            log::Level::Debug => "DEBUG",
            log::Level::Trace => "TRACE",
        };
        self.write_raw(&format!(
            "[{}] [{}] [{}] {}\n",
            timestamp,
            level_str,
            record.target(),
            record.args()
        ));
    }
}

static LOGGER: OnceLock<Mutex<DebugLogger>> = OnceLock::new();

fn get_logger() -> &'static Mutex<DebugLogger> {
    LOGGER.get_or_init(|| Mutex::new(DebugLogger::new()))
}

fn get_timestamp() -> String {
    let now = SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .expect("SystemTime::now() is always after UNIX_EPOCH");
    format!("{}.{:06}", now.as_secs(), now.subsec_micros())
}

/// Get the path to the debug log file.
pub fn log_path() -> std::path::PathBuf {
    std::env::temp_dir().join("par_term_debug.log")
}

/// Check if debugging is enabled at given level (for custom debug macros)
pub fn is_enabled(level: DebugLevel) -> bool {
    let logger = get_logger().lock();
    level <= logger.level
}

/// Log a message at specified level (for custom debug macros)
pub fn log(level: DebugLevel, category: &str, msg: &str) {
    let mut logger = get_logger().lock();
    logger.log(level, category, msg);
}

/// Log formatted message (for custom debug macros)
pub fn logf(level: DebugLevel, category: &str, args: fmt::Arguments) {
    if is_enabled(level) {
        log(level, category, &format!("{}", args));
    }
}

// ============================================================================
// log crate bridge — routes log::info!() etc. to the debug log file
// ============================================================================

/// Bridge that implements the `log` crate's `Log` trait, routing all log
/// output to the par-term debug log file. Optionally mirrors to stderr
/// when `RUST_LOG` is set (for terminal debugging).
struct LogCrateBridge {
    /// Maximum level to accept (parsed from RUST_LOG, default: Info)
    max_level: log::LevelFilter,
    /// Whether to also write to stderr (true when RUST_LOG is explicitly set)
    mirror_stderr: bool,
    /// Module-level filters (module_prefix, max_level) for noisy crates
    module_filters: Vec<(&'static str, log::LevelFilter)>,
}

impl LogCrateBridge {
    fn new() -> Self {
        let rust_log_set = std::env::var("RUST_LOG").is_ok();
        let max_level = if rust_log_set {
            // Parse RUST_LOG for the default level (simplified: just use the first token)
            match std::env::var("RUST_LOG")
                .unwrap_or_default()
                .to_lowercase()
                .as_str()
            {
                "trace" => log::LevelFilter::Trace,
                "debug" => log::LevelFilter::Debug,
                "info" => log::LevelFilter::Info,
                "warn" => log::LevelFilter::Warn,
                "error" => log::LevelFilter::Error,
                "off" => log::LevelFilter::Off,
                _ => log::LevelFilter::Info, // default if RUST_LOG has module-specific syntax
            }
        } else {
            // No RUST_LOG: capture info and above to the log file
            log::LevelFilter::Info
        };

        LogCrateBridge {
            max_level,
            mirror_stderr: rust_log_set,
            module_filters: vec![
                ("wgpu_core", log::LevelFilter::Warn),
                ("wgpu_hal", log::LevelFilter::Warn),
                ("naga", log::LevelFilter::Warn),
                ("rodio", log::LevelFilter::Error),
                ("cpal", log::LevelFilter::Error),
            ],
        }
    }

    fn level_for_module(&self, target: &str) -> log::LevelFilter {
        for (prefix, filter) in &self.module_filters {
            if target.starts_with(prefix) {
                return *filter;
            }
        }
        self.max_level
    }
}

impl log::Log for LogCrateBridge {
    fn enabled(&self, metadata: &log::Metadata) -> bool {
        metadata.level() <= self.level_for_module(metadata.target())
    }

    fn log(&self, record: &log::Record) {
        if !self.enabled(record.metadata()) {
            return;
        }

        // Write to the debug log file
        let mut logger = get_logger().lock();
        logger.log_record(record);
        drop(logger);

        // Mirror to stderr when RUST_LOG is set (for terminal debugging)
        if self.mirror_stderr {
            eprintln!(
                "[{}] {}: {}",
                record.level(),
                record.target(),
                record.args()
            );
        }
    }

    fn flush(&self) {}
}

/// Initialize the `log` crate bridge. Call this once from main() instead of env_logger::init().
/// Routes all `log::info!()` etc. calls to the par-term debug log file.
/// When `RUST_LOG` is set, also mirrors to stderr for terminal debugging.
///
/// `level_override` allows CLI or config to set the level. If `None`, uses
/// `RUST_LOG` env var (or defaults to `Info`).
pub fn init_log_bridge(level_override: Option<log::LevelFilter>) {
    // Force logger initialization (opens the log file)
    let _ = get_logger();

    let bridge = LogCrateBridge::new();
    // CLI/config override takes precedence, then RUST_LOG, then default
    let max_level = level_override.unwrap_or(bridge.max_level);

    // Install as the global logger
    if log::set_boxed_logger(Box::new(bridge)).is_ok() {
        log::set_max_level(max_level);
    }
}

/// Update the log level at runtime (e.g., from settings UI).
/// This only changes `log::max_level()` — the bridge itself always writes
/// whatever passes the filter.
pub fn set_log_level(level: log::LevelFilter) {
    log::set_max_level(level);
}

// ============================================================================
// try_lock failure telemetry
// ============================================================================

/// Total number of `try_lock()` calls that returned `Err` (lock contended) across all
/// call sites in the application.  Incremented via [`record_try_lock_failure`].
///
/// Deliberately a module-level static so it is zero-cost when the counter is never
/// read — the increment itself is a single `fetch_add(Relaxed)`.
pub static TRY_LOCK_FAILURE_COUNT: std::sync::atomic::AtomicU64 =
    std::sync::atomic::AtomicU64::new(0);

/// The value of [`TRY_LOCK_FAILURE_COUNT`] at the time of the last periodic telemetry
/// log.  Used by [`maybe_log_try_lock_telemetry`] to avoid emitting redundant log lines.
static TRY_LOCK_LAST_REPORTED: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0);

/// Record one `try_lock()` failure.
///
/// Increments [`TRY_LOCK_FAILURE_COUNT`] and emits a `CONCURRENCY` debug-log entry
/// (visible at `DEBUG_LEVEL >= 3`).
///
/// # Arguments
/// * `site` - A short, human-readable label identifying the call site
///   (e.g., `"resize"`, `"theme_change"`, `"focus_event"`).
#[inline]
pub fn record_try_lock_failure(site: &str) {
    let total = TRY_LOCK_FAILURE_COUNT.fetch_add(1, std::sync::atomic::Ordering::Relaxed) + 1;
    logf(
        DebugLevel::Debug,
        "CONCURRENCY",
        format_args!("try_lock() miss at '{}' (lifetime total: {})", site, total),
    );
}

/// Return the current lifetime total of `try_lock()` failures.
///
/// Intended for periodic telemetry reporting (e.g., once per second in
/// [`about_to_wait`][`crate::app::handler::window_state_impl::about_to_wait`]).
#[inline]
pub fn try_lock_failure_count() -> u64 {
    TRY_LOCK_FAILURE_COUNT.load(std::sync::atomic::Ordering::Relaxed)
}

/// Emit a periodic telemetry summary if new `try_lock()` failures have been recorded
/// since the last call.
///
/// This is designed to be called from `about_to_wait` (once per event-loop iteration)
/// so that lock-contention pressure is surfaced in the debug log without generating
/// per-failure log spam at higher rates.  The log entry is only written when at least
/// one new failure occurred since the previous call.
pub fn maybe_log_try_lock_telemetry() {
    let current = TRY_LOCK_FAILURE_COUNT.load(std::sync::atomic::Ordering::Relaxed);
    let last = TRY_LOCK_LAST_REPORTED.load(std::sync::atomic::Ordering::Relaxed);
    if current > last {
        // Use compare_exchange to ensure only one caller logs when there are
        // multiple windows.  The "loser" simply skips this cycle.
        if TRY_LOCK_LAST_REPORTED
            .compare_exchange(
                last,
                current,
                std::sync::atomic::Ordering::Relaxed,
                std::sync::atomic::Ordering::Relaxed,
            )
            .is_ok()
        {
            let new_since_last = current - last;
            logf(
                DebugLevel::Info,
                "CONCURRENCY",
                format_args!(
                    "try_lock telemetry: {} new failure(s) this interval, {} lifetime total",
                    new_since_last, current
                ),
            );
        }
    }
}

// ============================================================================
// Custom debug macros (unchanged, controlled by DEBUG_LEVEL)
// ============================================================================

#[macro_export]
macro_rules! debug_error {
    ($category:expr, $($arg:tt)*) => {
        $crate::debug::logf($crate::debug::DebugLevel::Error, $category, format_args!($($arg)*))
    };
}

#[macro_export]
macro_rules! debug_info {
    ($category:expr, $($arg:tt)*) => {
        $crate::debug::logf($crate::debug::DebugLevel::Info, $category, format_args!($($arg)*))
    };
}

#[macro_export]
macro_rules! debug_log {
    ($category:expr, $($arg:tt)*) => {
        $crate::debug::logf($crate::debug::DebugLevel::Debug, $category, format_args!($($arg)*))
    };
}

#[macro_export]
macro_rules! debug_trace {
    ($category:expr, $($arg:tt)*) => {
        $crate::debug::logf($crate::debug::DebugLevel::Trace, $category, format_args!($($arg)*))
    };
}

// ============================================================================
// Combined debug-log macros (R-18)
//
// Several call sites emit both a `crate::debug_error!` (routed to the custom
// debug log file, controlled by DEBUG_LEVEL) AND a `log::warn!` / `log::error!`
// (routed through the standard `log` crate bridge, controlled by RUST_LOG).
//
// These two-line patterns are collapsed into a single `debug_and_log!` call:
//
//   debug_and_log!(WARN, "CATEGORY", "message {}", var);
//   debug_and_log!(ERROR, "CATEGORY", "message {}", var);
//
// The macro writes to the custom debug log at the `Error` level **and** emits
// the same message through `log::warn!` or `log::error!` respectively.
// ============================================================================

/// Emit a message to both the custom debug log (at `Error` level) and the
/// standard `log` crate at `log::warn!` level.
///
/// # Example
/// ```ignore
/// debug_and_log!(WARN, "TMUX", "Failed to attach session '{}': {}", name, e);
/// ```
#[macro_export]
macro_rules! debug_and_log_warn {
    ($category:expr, $($arg:tt)*) => {{
        $crate::debug::logf(
            $crate::debug::DebugLevel::Error,
            $category,
            format_args!($($arg)*),
        );
        log::warn!($($arg)*);
    }};
}

/// Emit a message to both the custom debug log (at `Error` level) and the
/// standard `log` crate at `log::error!` level.
///
/// # Example
/// ```ignore
/// debug_and_log_error!("SCRIPT", "Script '{}' failed: {}", name, e);
/// ```
#[macro_export]
macro_rules! debug_and_log_error {
    ($category:expr, $($arg:tt)*) => {{
        $crate::debug::logf(
            $crate::debug::DebugLevel::Error,
            $category,
            format_args!($($arg)*),
        );
        log::error!($($arg)*);
    }};
}