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};
#[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,
}
}
}
struct DebugLogger {
level: DebugLevel,
file: Option<std::fs::File>,
mirror_stderr: bool,
}
fn rotate_log_file(log_path: &std::path::Path) {
let Ok(meta) = log_path.symlink_metadata() else {
return;
};
if !meta.is_file() || meta.len() == 0 {
return;
}
#[cfg(unix)]
{
use std::os::unix::fs::MetadataExt;
if meta.uid() != unsafe { libc::getuid() } {
return;
}
}
let mut rolled = log_path.as_os_str().to_owned();
rolled.push(".1");
let _ = std::fs::rename(log_path, std::path::PathBuf::from(rolled));
}
fn open_log_file(log_path: &std::path::Path) -> Option<std::fs::File> {
if log_path
.symlink_metadata()
.map(|m| m.file_type().is_symlink())
.unwrap_or(false)
{
let _ = std::fs::remove_file(log_path);
}
rotate_log_file(log_path);
#[cfg(unix)]
{
use std::os::unix::fs::{MetadataExt, OpenOptionsExt};
OpenOptions::new()
.write(true)
.truncate(true)
.create(true)
.mode(0o600)
.custom_flags(libc::O_NOFOLLOW)
.open(log_path)
.ok()
.filter(|f| {
let our_uid = unsafe { libc::getuid() };
match f.metadata() {
Ok(meta) if meta.uid() == our_uid => true,
Ok(meta) => {
eprintln!(
"par-term: refusing to write {} — it is owned by uid {}, not \
this user. Debug file logging is disabled.",
log_path.display(),
meta.uid()
);
false
}
Err(_) => false,
}
})
}
#[cfg(not(unix))]
{
OpenOptions::new()
.write(true)
.truncate(true)
.create(true)
.open(log_path)
.ok()
}
}
impl DebugLogger {
fn new() -> Self {
let level = DebugLevel::from_env();
let file = open_log_file(&log_path());
let mirror_stderr = std::env::var("RUST_LOG").is_ok();
let mut logger = DebugLogger {
level,
file,
mirror_stderr,
};
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();
}
}
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
));
if self.mirror_stderr {
eprintln!("[{}] {}: {}", level_str.trim_end(), category, msg);
}
}
}
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())
}
pub fn log_path() -> std::path::PathBuf {
std::env::temp_dir().join("par_term_debug.log")
}
pub fn is_enabled(level: DebugLevel) -> bool {
let logger = get_logger().lock();
level <= logger.level
}
pub fn log(level: DebugLevel, category: &str, msg: &str) {
let mut logger = get_logger().lock();
logger.log(level, category, msg);
}
pub fn logf(level: DebugLevel, category: &str, args: fmt::Arguments) {
if is_enabled(level) {
log(level, category, &format!("{}", args));
}
}
pub fn try_logf(level: DebugLevel, category: &str, args: fmt::Arguments) -> bool {
let level_str = match level {
DebugLevel::Error => "ERROR",
DebugLevel::Info => "INFO ",
DebugLevel::Debug => "DEBUG",
DebugLevel::Trace => "TRACE",
DebugLevel::Off => return false,
};
let Some(logger) = LOGGER.get() else {
return false;
};
let Some(mut logger) = logger.try_lock() else {
return false;
};
logger.write_raw(&format!(
"[{}] [{}] [{}] {}\n",
get_timestamp(),
level_str,
category,
args
));
true
}
struct LogCrateBridge {
max_level: log::LevelFilter,
mirror_stderr: bool,
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 {
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, }
} else {
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;
}
let mut logger = get_logger().lock();
logger.log_record(record);
drop(logger);
if self.mirror_stderr {
eprintln!(
"[{}] {}: {}",
record.level(),
record.target(),
record.args()
);
}
}
fn flush(&self) {}
}
pub fn init_log_bridge(level_override: Option<log::LevelFilter>) {
let _ = get_logger();
let bridge = LogCrateBridge::new();
let max_level = level_override.unwrap_or(bridge.max_level);
if log::set_boxed_logger(Box::new(bridge)).is_ok() {
log::set_max_level(max_level);
}
}
pub fn set_log_level(level: log::LevelFilter) {
log::set_max_level(level);
}
pub static TRY_LOCK_FAILURE_COUNT: std::sync::atomic::AtomicU64 =
std::sync::atomic::AtomicU64::new(0);
static TRY_LOCK_LAST_REPORTED: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0);
#[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),
);
}
#[inline]
pub fn try_lock_failure_count() -> u64 {
TRY_LOCK_FAILURE_COUNT.load(std::sync::atomic::Ordering::Relaxed)
}
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 {
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
),
);
}
}
}
#[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)*))
};
}
#[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)*);
}};
}
#[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)*);
}};
}
#[cfg(test)]
mod tests {
use super::*;
#[cfg(unix)]
#[test]
fn log_file_is_created_owner_only() {
use std::os::unix::fs::PermissionsExt;
let dir = tempfile::tempdir().expect("temp dir");
let path = dir.path().join("par_term_debug.log");
let file = open_log_file(&path).expect("log file opens");
drop(file);
let mode = std::fs::metadata(&path)
.expect("log file created")
.permissions()
.mode();
assert_eq!(
mode & 0o777,
0o600,
"debug log must not be group/world readable"
);
}
#[cfg(unix)]
#[test]
fn log_file_open_does_not_follow_a_planted_symlink() {
let dir = tempfile::tempdir().expect("temp dir");
let path = dir.path().join("par_term_debug.log");
let target = dir.path().join("victim");
std::fs::write(&target, "original").expect("seed symlink target");
std::os::unix::fs::symlink(&target, &path).expect("plant symlink");
let mut file = open_log_file(&path).expect("log file opens");
std::io::Write::write_all(&mut file, b"leaked").expect("write");
drop(file);
assert_eq!(
std::fs::read_to_string(&target).expect("read target"),
"original",
"the log must not be written through the planted symlink"
);
}
#[test]
fn log_file_is_truncated_on_reopen() {
let dir = tempfile::tempdir().expect("temp dir");
let path = dir.path().join("par_term_debug.log");
std::fs::write(&path, "stale session output").expect("seed log");
let file = open_log_file(&path).expect("log file opens");
drop(file);
assert_eq!(std::fs::read_to_string(&path).expect("read log"), "");
}
#[test]
fn previous_log_is_rolled_aside_on_reopen() {
let dir = tempfile::tempdir().expect("temp dir");
let path = dir.path().join("par_term_debug.log");
let rolled = dir.path().join("par_term_debug.log.1");
std::fs::write(&path, "PANIC report from the run that crashed").expect("seed log");
let file = open_log_file(&path).expect("log file opens");
drop(file);
assert_eq!(
std::fs::read_to_string(&rolled).expect("previous log rolled aside"),
"PANIC report from the run that crashed"
);
}
#[test]
fn an_empty_log_is_not_rotated() {
let dir = tempfile::tempdir().expect("temp dir");
let path = dir.path().join("par_term_debug.log");
let rolled = dir.path().join("par_term_debug.log.1");
std::fs::write(&rolled, "the log worth keeping").expect("seed rolled log");
std::fs::write(&path, "").expect("seed empty log");
let file = open_log_file(&path).expect("log file opens");
drop(file);
assert_eq!(
std::fs::read_to_string(&rolled).expect("read rolled log"),
"the log worth keeping",
"an empty log must not overwrite the previous rotation"
);
}
#[test]
fn try_logf_neither_blocks_nor_initializes_the_logger() {
let wrote = try_logf(DebugLevel::Error, "TEST", format_args!("no deadlock"));
assert!(
!wrote || LOGGER.get().is_some(),
"try_logf reported a write with no logger installed"
);
assert!(
!try_logf(DebugLevel::Off, "TEST", format_args!("ignored")),
"DebugLevel::Off has no line format and must never be written"
);
if let Some(logger) = LOGGER.get() {
let held = logger.lock();
assert!(
!try_logf(DebugLevel::Error, "TEST", format_args!("contended")),
"try_logf must drop the line while the logger mutex is held"
);
drop(held);
}
}
#[test]
fn the_panic_report_never_blocks_on_the_logger() {
use crate::session::crash_guard::{PanicReport, SaveOutcome, report_fields};
fn fields(outcome: Option<SaveOutcome>) -> PanicReport<'static> {
PanicReport {
thread_name: "test",
file: "src/debug.rs",
line: 1,
column: 1,
payload: "provoked",
outcome,
}
}
for outcome in [
None,
Some(SaveOutcome::Saved),
Some(SaveOutcome::NoSnapshot),
Some(SaveOutcome::AlreadySaved),
Some(SaveOutcome::WriteFailed),
] {
report_fields(fields(outcome));
}
let Some(logger) = LOGGER.get() else {
return;
};
let held = logger.lock();
let (tx, rx) = std::sync::mpsc::channel();
std::thread::spawn(move || {
report_fields(fields(Some(SaveOutcome::Saved)));
let _ = tx.send(());
});
let finished = rx.recv_timeout(std::time::Duration::from_secs(10)).is_ok();
drop(held);
assert!(
finished,
"the panic hook's report step blocked on the logger mutex"
);
}
}