|
| 1 | +//! ShadeCore logging utilities. |
| 2 | +//! |
| 3 | +//! Design goals |
| 4 | +//! - Every ShadeCore log line is shaped like: |
| 5 | +//! <timestamp> [TAG][thread] message |
| 6 | +//! - Works on all platforms with std only (no extra deps). |
| 7 | +//! - Optional file sink for audit/debug. |
| 8 | +//! - Optional piping of child-process stdout/stderr into the same log format. |
| 9 | +//! |
| 10 | +//! NOTE: Some platform/framework messages (e.g. macOS IMK) bypass this logger and may still |
| 11 | +//! appear unformatted; those are emitted by the OS/framework itself. |
| 12 | +
|
| 13 | +use std::fs::OpenOptions; |
| 14 | +use std::io::{BufRead, BufReader, Read, Write}; |
| 15 | +use std::path::PathBuf; |
| 16 | +use std::sync::atomic::{AtomicU64, Ordering}; |
| 17 | +use std::sync::{Mutex, OnceLock}; |
| 18 | +use std::time::{SystemTime, UNIX_EPOCH}; |
| 19 | + |
| 20 | +static LOG_FILE: OnceLock<Mutex<Option<std::fs::File>>> = OnceLock::new(); |
| 21 | +static RUN_ID: OnceLock<String> = OnceLock::new(); |
| 22 | +static SESSION_COUNTER: AtomicU64 = AtomicU64::new(0); |
| 23 | + |
| 24 | +/// Initialize logging. Call once at startup. |
| 25 | +/// - If `log_file` is Some, we append all log lines to that path. |
| 26 | +/// - Always logs to stderr as the primary sink. |
| 27 | +/// |
| 28 | +/// Returns the generated run_id. |
| 29 | +pub fn init(log_file: Option<PathBuf>) -> String { |
| 30 | + let rid = RUN_ID |
| 31 | + .get_or_init(|| { |
| 32 | + // Short correlation id: time xor pid (good enough for debugging/audit grouping) |
| 33 | + let now = SystemTime::now().duration_since(UNIX_EPOCH).unwrap_or_default(); |
| 34 | + format!("{:08x}", (now.as_nanos() as u64) ^ (std::process::id() as u64)) |
| 35 | + }) |
| 36 | + .clone(); |
| 37 | + |
| 38 | + let _ = LOG_FILE.get_or_init(|| Mutex::new(None)); |
| 39 | + |
| 40 | + if let Some(path) = log_file { |
| 41 | + match OpenOptions::new().create(true).append(true).open(&path) { |
| 42 | + Ok(f) => { |
| 43 | + if let Some(m) = LOG_FILE.get() { |
| 44 | + *m.lock().unwrap() = Some(f); |
| 45 | + } |
| 46 | + } |
| 47 | + Err(_) => { |
| 48 | + // Can't call log* macros here (they depend on log_line), so emit directly. |
| 49 | + eprintln!( |
| 50 | + "{} [WARN][{}] failed to open log file sink", |
| 51 | + log_timestamp(), |
| 52 | + log_thread_name() |
| 53 | + ); |
| 54 | + } |
| 55 | + } |
| 56 | + } |
| 57 | + |
| 58 | + rid |
| 59 | +} |
| 60 | + |
| 61 | +/// Current run id (empty if init() wasn't called). |
| 62 | +pub fn run_id() -> &'static str { |
| 63 | + RUN_ID.get().map(|s| s.as_str()).unwrap_or("") |
| 64 | +} |
| 65 | + |
| 66 | +/// Make a short session id for correlating operations (e.g. recording sessions). |
| 67 | +pub fn make_session_id(prefix: &str) -> String { |
| 68 | + let n = SESSION_COUNTER.fetch_add(1, Ordering::Relaxed); |
| 69 | + format!("{prefix}_{}_{}", compact_utc_timestamp(), format!("{:04}", n)) |
| 70 | +} |
| 71 | + |
| 72 | +/// Pipe a Read stream (child stdout/stderr) into the logger on its own thread. |
| 73 | +pub fn spawn_pipe_thread<R: Read + Send + 'static>( |
| 74 | + thread_name: &str, |
| 75 | + tag: &str, |
| 76 | + reader: R, |
| 77 | + as_warn: bool, |
| 78 | +) { |
| 79 | + let tag = tag.to_string(); |
| 80 | + let tname = thread_name.to_string(); |
| 81 | + let _ = std::thread::Builder::new() |
| 82 | + .name(tname) |
| 83 | + .spawn(move || { |
| 84 | + let br = BufReader::new(reader); |
| 85 | + for line in br.lines().flatten() { |
| 86 | + if as_warn { |
| 87 | + log_line("WARN", &tag, &line); |
| 88 | + } else { |
| 89 | + log_line("INFO", &tag, &line); |
| 90 | + } |
| 91 | + } |
| 92 | + }); |
| 93 | +} |
| 94 | + |
| 95 | +/// Timestamp used in logs: `YYYY-MM-DD HH:MM:SS.mmm` (UTC). |
| 96 | +pub fn log_timestamp() -> String { |
| 97 | + let now = SystemTime::now().duration_since(UNIX_EPOCH).unwrap_or_default(); |
| 98 | + let secs = now.as_secs() as i64; |
| 99 | + let ms = now.subsec_millis() as i64; |
| 100 | + |
| 101 | + let days = secs.div_euclid(86_400); |
| 102 | + let sod = secs.rem_euclid(86_400); |
| 103 | + |
| 104 | + let (year, month, day) = civil_from_days(days); |
| 105 | + let hour = (sod / 3600) as i64; |
| 106 | + let min = ((sod % 3600) / 60) as i64; |
| 107 | + let sec = (sod % 60) as i64; |
| 108 | + |
| 109 | + format!( |
| 110 | + "{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}", |
| 111 | + year, month, day, hour, min, sec, ms |
| 112 | + ) |
| 113 | +} |
| 114 | + |
| 115 | +/// Best-effort thread name for log prefix. |
| 116 | +pub fn log_thread_name() -> String { |
| 117 | + std::thread::current().name().unwrap_or("main").to_string() |
| 118 | +} |
| 119 | + |
| 120 | +/// Write one fully formatted line to stderr + optional file sink. |
| 121 | +/// |
| 122 | +/// This must be visible to the macros (crate scope). |
| 123 | +pub(crate) fn log_line(_level: &str, tag: &str, msg: &str) { |
| 124 | + let line = format!("{} [{}][{}] {}", log_timestamp(), tag, log_thread_name(), msg); |
| 125 | + |
| 126 | + // stderr is the canonical sink |
| 127 | + eprintln!("{line}"); |
| 128 | + |
| 129 | + // optional file sink |
| 130 | + if let Some(m) = LOG_FILE.get() { |
| 131 | + if let Ok(mut guard) = m.lock() { |
| 132 | + if let Some(f) = guard.as_mut() { |
| 133 | + let _ = writeln!(f, "{line}"); |
| 134 | + let _ = f.flush(); |
| 135 | + } |
| 136 | + } |
| 137 | + } |
| 138 | +} |
| 139 | + |
| 140 | +// Compact timestamp for ids: `YYYYMMDDThhmmssZ` (UTC). |
| 141 | +fn compact_utc_timestamp() -> String { |
| 142 | + let now = SystemTime::now().duration_since(UNIX_EPOCH).unwrap_or_default(); |
| 143 | + let secs = now.as_secs() as i64; |
| 144 | + |
| 145 | + let days = secs.div_euclid(86_400); |
| 146 | + let sod = secs.rem_euclid(86_400); |
| 147 | + |
| 148 | + let (year, month, day) = civil_from_days(days); |
| 149 | + let hour = (sod / 3600) as i64; |
| 150 | + let min = ((sod % 3600) / 60) as i64; |
| 151 | + let sec = (sod % 60) as i64; |
| 152 | + |
| 153 | + format!("{:04}{:02}{:02}T{:02}{:02}{:02}Z", year, month, day, hour, min, sec) |
| 154 | +} |
| 155 | + |
| 156 | +// Howard Hinnant civil_from_days algorithm (reimplemented). |
| 157 | +// Converts days since Unix epoch (1970-01-01) to Gregorian Y-M-D in UTC. |
| 158 | +fn civil_from_days(z: i64) -> (i64, i64, i64) { |
| 159 | + let z = z + 719468; |
| 160 | + let era = (if z >= 0 { z } else { z - 146096 }).div_euclid(146097); |
| 161 | + let doe = z - era * 146097; |
| 162 | + let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096).div_euclid(365); |
| 163 | + let y = yoe + era * 400; |
| 164 | + let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); |
| 165 | + let mp = (5 * doy + 2).div_euclid(153); |
| 166 | + let d = doy - (153 * mp + 2).div_euclid(5) + 1; |
| 167 | + let m = mp + if mp < 10 { 3 } else { -9 }; |
| 168 | + let year = y + if m <= 2 { 1 } else { 0 }; |
| 169 | + (year, m, d) |
| 170 | +} |
| 171 | + |
| 172 | +#[macro_export] |
| 173 | +macro_rules! logi { |
| 174 | + ($tag:expr, $($arg:tt)*) => {{ |
| 175 | + let msg = format!($($arg)*); |
| 176 | + $crate::logging::log_line("INFO", $tag, &msg); |
| 177 | + }}; |
| 178 | +} |
| 179 | + |
| 180 | +#[macro_export] |
| 181 | +macro_rules! logw { |
| 182 | + ($tag:expr, $($arg:tt)*) => {{ |
| 183 | + let msg = format!($($arg)*); |
| 184 | + $crate::logging::log_line("WARN", $tag, &msg); |
| 185 | + }}; |
| 186 | +} |
| 187 | + |
| 188 | +#[macro_export] |
| 189 | +macro_rules! loge { |
| 190 | + ($tag:expr, $($arg:tt)*) => {{ |
| 191 | + let msg = format!($($arg)*); |
| 192 | + $crate::logging::log_line("ERROR", $tag, &msg); |
| 193 | + }}; |
| 194 | +} |
0 commit comments