purple_ssh/
logging.rs

1use std::fs;
2use std::io::Write;
3use std::path::{Path, PathBuf};
4
5use log::LevelFilter;
6use simplelog::{
7    ColorChoice, CombinedLogger, ConfigBuilder, SharedLogger, TermLogger, TerminalMode, WriteLogger,
8};
9
10// Fault domain convention: every log statement carries a prefix.
11// - [external] = an external tool, binary, network or remote host failed.
12// - [config]   = a user config, parse or user-data problem.
13// - [purple]   = our own internal state, flow or invariant.
14
15const MAX_LOG_SIZE: u64 = 5 * 1024 * 1024; // 5MB
16
17/// Return the path to the log file: ~/.purple/purple.log
18pub fn log_path(paths: Option<&crate::runtime::env::Paths>) -> Option<PathBuf> {
19    paths.map(crate::runtime::env::Paths::log_file)
20}
21
22/// Rotate log file if it exceeds MAX_LOG_SIZE.
23/// Renames purple.log -> purple.log.1 (overwrites previous backup).
24fn rotate_if_needed(path: &Path) {
25    if let Ok(meta) = fs::metadata(path)
26        && meta.len() > MAX_LOG_SIZE
27    {
28        let backup = path.with_file_name("purple.log.1");
29        let _ = fs::rename(path, backup);
30    }
31}
32
33/// Determine log level. `env_override` takes precedence over `verbose` flag.
34fn resolve_level(verbose: bool, env_override: Option<&str>) -> LevelFilter {
35    if let Some(val) = env_override {
36        match val.to_lowercase().as_str() {
37            "trace" => return LevelFilter::Trace,
38            "debug" => return LevelFilter::Debug,
39            "info" => return LevelFilter::Info,
40            "warn" => return LevelFilter::Warn,
41            "error" => return LevelFilter::Error,
42            "off" => return LevelFilter::Off,
43            _ => {}
44        }
45    }
46    if verbose {
47        LevelFilter::Debug
48    } else {
49        LevelFilter::Warn
50    }
51}
52
53/// Initialize logging. Call once at the start of main().
54///
55/// - `verbose`: whether --verbose was passed
56/// - `cli_stderr`: if true, also log to stderr (for CLI subcommands, not TUI)
57pub fn init(verbose: bool, cli_stderr: bool, env: &crate::runtime::env::Env) {
58    let Some(path) = log_path(env.paths()) else {
59        return;
60    };
61
62    if let Some(parent) = path.parent() {
63        let _ = fs::create_dir_all(parent);
64    }
65
66    rotate_if_needed(&path);
67
68    let level = resolve_level(verbose, env.var("PURPLE_LOG"));
69    let config = ConfigBuilder::new()
70        .set_time_format_rfc3339()
71        .set_target_level(LevelFilter::Off)
72        .set_thread_level(LevelFilter::Off)
73        .build();
74
75    let mut loggers: Vec<Box<dyn SharedLogger>> = Vec::with_capacity(2);
76
77    if let Ok(file) = fs::OpenOptions::new().create(true).append(true).open(&path) {
78        loggers.push(WriteLogger::new(level, config.clone(), file));
79    }
80
81    if cli_stderr {
82        loggers.push(TermLogger::new(
83            level,
84            config,
85            TerminalMode::Stderr,
86            ColorChoice::Auto,
87        ));
88    }
89
90    if !loggers.is_empty()
91        && let Err(e) = CombinedLogger::init(loggers)
92    {
93        eprintln!("{}", crate::messages::logging::init_failed(&e));
94    }
95}
96
97/// Format current UTC time as YYYY-MM-DD HH:MM:SS.
98fn format_now_utc() -> String {
99    let now = std::time::SystemTime::now();
100    let secs = now
101        .duration_since(std::time::UNIX_EPOCH)
102        .unwrap_or_default()
103        .as_secs();
104    let days = secs / 86400;
105    let time_of_day = secs % 86400;
106    let hours = time_of_day / 3600;
107    let minutes = (time_of_day % 3600) / 60;
108    let seconds = time_of_day % 60;
109
110    let (year, month, day) = epoch_days_to_date(days);
111    format!("{year:04}-{month:02}-{day:02} {hours:02}:{minutes:02}:{seconds:02}Z")
112}
113
114/// Convert days since Unix epoch to (year, month, day).
115/// Algorithm from <http://howardhinnant.github.io/date_algorithms.html>.
116fn epoch_days_to_date(days: u64) -> (u64, u64, u64) {
117    let z = days + 719_468;
118    let era = z / 146_097;
119    let doe = z % 146_097;
120    let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146_096) / 365;
121    let y = yoe + era * 400;
122    let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
123    let mp = (5 * doy + 2) / 153;
124    let d = doy - (153 * mp + 2) / 5 + 1;
125    let m = if mp < 10 { mp + 3 } else { mp - 9 };
126    let y = if m <= 2 { y + 1 } else { y };
127    (y, m, d)
128}
129
130/// Startup banner info. Struct avoids argument-order bugs between &str params.
131pub struct BannerInfo<'a> {
132    pub version: &'a str,
133    pub config_path: &'a str,
134    pub providers: &'a [String],
135    pub askpass_sources: &'a [String],
136    pub vault_ssh_info: Option<&'a str>,
137    pub ssh_version: &'a str,
138    pub term: &'a str,
139    pub colorterm: &'a str,
140    pub level: &'a str,
141    /// Theme currently in effect (loaded from preferences or `--theme`).
142    pub theme: &'a str,
143    /// Total number of host entries parsed from the SSH config.
144    pub hosts: usize,
145    /// Total number of patterns (wildcard / multi-alias `Host` lines).
146    pub patterns: usize,
147    /// Total number of snippets loaded from the snippet store.
148    pub snippets: usize,
149    /// Comma-separated list of env vars that affect proxy behaviour (HTTP_PROXY,
150    /// HTTPS_PROXY, NO_PROXY) when any are set. `"none"` when none are present.
151    pub proxy_env: &'a str,
152}
153
154/// Write startup banner directly to log file, bypassing level filters.
155/// All timestamps are UTC (suffixed with Z).
156///
157/// Note: writes directly to the log file, bypassing simplelog's CombinedLogger.
158/// This means the banner will not appear on stderr in CLI mode. This is intentional:
159/// the banner is diagnostic context for the log file, not user-facing output.
160pub fn write_banner(info: &BannerInfo<'_>, paths: Option<&crate::runtime::env::Paths>) {
161    let Some(path) = log_path(paths) else { return };
162    let Ok(mut file) = fs::OpenOptions::new().create(true).append(true).open(&path) else {
163        return;
164    };
165
166    let now = format_now_utc();
167    let os = std::env::consts::OS;
168    let arch = std::env::consts::ARCH;
169    let providers_joined = if info.providers.is_empty() {
170        "none".to_string()
171    } else {
172        info.providers.join(",")
173    };
174    let askpass_joined = if info.askpass_sources.is_empty() {
175        "none".to_string()
176    } else {
177        info.askpass_sources.join(",")
178    };
179
180    let mut banner = format!(
181        "--- purple v{} started at {now} ---\n\
182         \x20   os={os} arch={arch} config={}\n\
183         \x20   ssh={}\n\
184         \x20   term={} colorterm={}\n\
185         \x20   theme={}\n\
186         \x20   hosts={} patterns={} snippets={}\n\
187         \x20   providers={providers_joined}\n\
188         \x20   askpass={askpass_joined}\n\
189         \x20   proxy_env={}\n",
190        info.version,
191        info.config_path,
192        info.ssh_version,
193        info.term,
194        info.colorterm,
195        info.theme,
196        info.hosts,
197        info.patterns,
198        info.snippets,
199        info.proxy_env,
200    );
201    if let Some(vault_info) = info.vault_ssh_info {
202        banner.push_str(&format!("    vault_ssh={vault_info}\n"));
203    }
204    if let Some(p) = paths {
205        banner.push_str(&format!(
206            "    dirs: config={} data={} state={} cache={}\n",
207            p.config_dir().display(),
208            p.data_dir().display(),
209            p.state_dir().display(),
210            p.cache_dir().display()
211        ));
212    }
213    banner.push_str(&format!("    log_level={}\n", info.level));
214
215    // Note: banner lines use \x20 (space) prefix to prevent the Rust string
216    // continuation from collapsing leading whitespace. This is a rustfmt-safe
217    // idiom for multi-line format strings with indentation.
218
219    // Non-fatal: banner write failure does not affect logging
220    let _ = file.write_all(banner.as_bytes());
221}
222
223/// Return the effective log level name as a lowercase string.
224pub fn level_name(verbose: bool, env: &crate::runtime::env::Env) -> String {
225    resolve_level(verbose, env.var("PURPLE_LOG"))
226        .as_str()
227        .to_lowercase()
228}
229
230/// Detect SSH version by running `ssh -V` (output goes to stderr).
231/// Uses a 2-second timeout via mpsc channel to avoid hanging startup
232/// if the ssh binary is broken or on a slow filesystem.
233///
234/// On timeout, the spawned thread and child process continue running until
235/// `ssh -V` exits naturally. This is acceptable because `ssh -V` is
236/// near-instant and this only runs once at startup.
237pub fn detect_ssh_version() -> String {
238    use std::sync::mpsc;
239    use std::time::Duration;
240
241    let child = std::process::Command::new("ssh")
242        .arg("-V")
243        .stdout(std::process::Stdio::piped())
244        .stderr(std::process::Stdio::piped())
245        .spawn();
246
247    let Ok(child) = child else {
248        eprintln!("{}", crate::messages::logging::SSH_VERSION_FAILED);
249        return "unknown".to_string();
250    };
251
252    let (tx, rx) = mpsc::channel();
253    std::thread::spawn(move || {
254        let _ = tx.send(child.wait_with_output());
255    });
256
257    match rx.recv_timeout(Duration::from_secs(2)) {
258        Ok(Ok(output)) => {
259            let out = if output.stderr.is_empty() {
260                output.stdout
261            } else {
262                output.stderr
263            };
264            String::from_utf8(out)
265                .map(|s| s.trim().to_string())
266                .unwrap_or_else(|_| "unknown".to_string())
267        }
268        _ => "unknown".to_string(),
269    }
270}
271
272/// Thread-local log capture for tests. The global logger writes records into a
273/// per-thread sink that is only active inside `capture`, so parallel test
274/// threads never see each other's records and no global lock is needed.
275#[cfg(test)]
276pub(crate) mod capture {
277    use std::cell::RefCell;
278    use std::sync::Once;
279
280    use log::{Level, Log, Metadata, Record};
281
282    thread_local! {
283        static SINK: RefCell<Option<Vec<(Level, String)>>> = const { RefCell::new(None) };
284    }
285
286    struct CaptureLogger;
287
288    impl Log for CaptureLogger {
289        fn enabled(&self, _: &Metadata) -> bool {
290            true
291        }
292        fn log(&self, record: &Record) {
293            SINK.with(|s| {
294                if let Some(buf) = s.borrow_mut().as_mut() {
295                    buf.push((record.level(), record.args().to_string()));
296                }
297            });
298        }
299        fn flush(&self) {}
300    }
301
302    static LOGGER: CaptureLogger = CaptureLogger;
303    static INSTALL: Once = Once::new();
304
305    /// Run `f` and return every log record it emitted on this thread.
306    pub(crate) fn capture<F: FnOnce()>(f: F) -> Vec<(Level, String)> {
307        INSTALL.call_once(|| {
308            // No production test installs a logger, so this wins. If one ever
309            // does, our per-thread sink simply stays empty (set_logger errors).
310            if log::set_logger(&LOGGER).is_ok() {
311                log::set_max_level(log::LevelFilter::Trace);
312            }
313        });
314        SINK.with(|s| *s.borrow_mut() = Some(Vec::new()));
315        f();
316        SINK.with(|s| s.borrow_mut().take().unwrap_or_default())
317    }
318
319    /// True when any captured record matches `level` and contains `needle`.
320    pub(crate) fn has(records: &[(Level, String)], level: Level, needle: &str) -> bool {
321        records
322            .iter()
323            .any(|(lvl, msg)| *lvl == level && msg.contains(needle))
324    }
325}
326
327#[cfg(test)]
328mod tests {
329    use super::*;
330    use std::io::Write;
331
332    #[test]
333    fn rotate_if_needed_renames_large_file() {
334        let dir = tempfile::tempdir().unwrap();
335        let log = dir.path().join("purple.log");
336        let backup = dir.path().join("purple.log.1");
337
338        let mut f = fs::File::create(&log).unwrap();
339        let data = vec![0u8; (MAX_LOG_SIZE + 1) as usize];
340        f.write_all(&data).unwrap();
341        drop(f);
342
343        rotate_if_needed(&log);
344
345        assert!(!log.exists());
346        assert!(backup.exists());
347        assert!(fs::metadata(&backup).unwrap().len() > MAX_LOG_SIZE);
348    }
349
350    #[test]
351    fn rotate_if_needed_leaves_small_file() {
352        let dir = tempfile::tempdir().unwrap();
353        let log = dir.path().join("purple.log");
354
355        fs::write(&log, "small content").unwrap();
356
357        rotate_if_needed(&log);
358
359        assert!(log.exists());
360        assert!(!dir.path().join("purple.log.1").exists());
361    }
362
363    #[test]
364    fn rotate_if_needed_handles_missing_file() {
365        let dir = tempfile::tempdir().unwrap();
366        let log = dir.path().join("purple.log");
367
368        // Should not panic
369        rotate_if_needed(&log);
370    }
371
372    #[test]
373    fn resolve_level_defaults_to_warn() {
374        assert_eq!(resolve_level(false, None), LevelFilter::Warn);
375    }
376
377    #[test]
378    fn resolve_level_verbose_returns_debug() {
379        assert_eq!(resolve_level(true, None), LevelFilter::Debug);
380    }
381
382    #[test]
383    fn resolve_level_env_overrides_verbose() {
384        assert_eq!(resolve_level(false, Some("trace")), LevelFilter::Trace);
385        assert_eq!(resolve_level(true, Some("error")), LevelFilter::Error);
386    }
387
388    #[test]
389    fn resolve_level_ignores_unknown_env_value() {
390        assert_eq!(resolve_level(false, Some("bogus")), LevelFilter::Warn);
391        assert_eq!(resolve_level(true, Some("bogus")), LevelFilter::Debug);
392    }
393
394    #[test]
395    fn epoch_days_to_date_unix_epoch() {
396        // Day 0 = 1970-01-01
397        assert_eq!(epoch_days_to_date(0), (1970, 1, 1));
398    }
399
400    #[test]
401    fn epoch_days_to_date_known_date() {
402        // 2026-04-10 = day 20553
403        assert_eq!(epoch_days_to_date(20553), (2026, 4, 10));
404    }
405
406    #[test]
407    fn epoch_days_to_date_leap_year() {
408        // 2000-02-29 = day 11016
409        assert_eq!(epoch_days_to_date(11016), (2000, 2, 29));
410    }
411
412    #[test]
413    fn format_now_utc_returns_valid_timestamp() {
414        let ts = format_now_utc();
415        // Should be in YYYY-MM-DD HH:MM:SSZ format
416        assert_eq!(ts.len(), 20);
417        assert_eq!(&ts[4..5], "-");
418        assert_eq!(&ts[7..8], "-");
419        assert_eq!(&ts[10..11], " ");
420        assert_eq!(&ts[13..14], ":");
421        assert_eq!(&ts[16..17], ":");
422        assert!(ts.ends_with('Z'));
423    }
424
425    #[test]
426    fn log_path_ends_with_purple_log() {
427        let paths = crate::runtime::env::Paths::new("/home/u");
428        let path = log_path(Some(&paths)).expect("paths present");
429        assert!(path.ends_with(".purple/purple.log"));
430    }
431
432    #[test]
433    fn level_name_defaults_to_warn() {
434        // With no PURPLE_LOG in the injected env, the default is "warn".
435        let env = crate::runtime::env::Env::empty();
436        let name = level_name(false, &env);
437        assert_eq!(name, "warn");
438    }
439
440    #[test]
441    fn write_banner_creates_output() {
442        let info = BannerInfo {
443            version: "0.0.0-test",
444            config_path: "/tmp/config",
445            providers: &["testprov".to_string()],
446            askpass_sources: &["keychain:".to_string()],
447            vault_ssh_info: Some("enabled (addr=https://vault:8200)"),
448            ssh_version: "OpenSSH_9.0",
449            term: "xterm-256color",
450            colorterm: "truecolor",
451            level: "warn",
452            theme: "Purple",
453            hosts: 42,
454            patterns: 3,
455            snippets: 7,
456            proxy_env: "none",
457        };
458
459        // The banner lands in the state directory's log file and names the
460        // resolved category directories, so a support bundle shows where
461        // purple read and wrote.
462        let dir = tempfile::tempdir().unwrap();
463        let state = dir.path().join("state").to_string_lossy().to_string();
464        let paths = crate::runtime::env::Paths::resolve(dir.path(), move |k| {
465            (k == "XDG_STATE_HOME").then(|| state.clone())
466        });
467        std::fs::create_dir_all(paths.state_dir()).unwrap();
468        write_banner(&info, Some(&paths));
469
470        let body = std::fs::read_to_string(paths.log_file()).unwrap();
471        assert!(body.contains("--- purple v0.0.0-test started at "));
472        assert!(body.contains("hosts=42 patterns=3 snippets=7"));
473        assert!(body.contains("providers=testprov"));
474        assert!(body.contains("vault_ssh=enabled (addr=https://vault:8200)"));
475        assert!(
476            body.contains(&format!(
477                "dirs: config={} data={} state={} cache={}",
478                paths.config_dir().display(),
479                paths.data_dir().display(),
480                paths.state_dir().display(),
481                paths.cache_dir().display()
482            )),
483            "{body}"
484        );
485        assert!(body.contains("log_level=warn"));
486
487        let ts = format_now_utc();
488        assert!(ts.ends_with('Z'));
489        assert_eq!(ts.len(), 20);
490    }
491}
purple_ssh/logging.rs

purple_ssh/
logging.rs
