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    query_ssh_version().unwrap_or_else(|| {
239        eprintln!("{}", crate::messages::logging::SSH_VERSION_FAILED);
240        "unknown".to_string()
241    })
242}
243
244/// `ssh -V` output, or "unknown" when ssh gave no usable answer in time.
245/// `None` when ssh could not be started. Prints nothing, so the TUI can call
246/// it while it owns the terminal.
247pub(crate) fn query_ssh_version() -> Option<String> {
248    use std::sync::mpsc;
249    use std::time::Duration;
250
251    let child = std::process::Command::new("ssh")
252        .arg("-V")
253        .stdin(std::process::Stdio::null())
254        .stdout(std::process::Stdio::piped())
255        .stderr(std::process::Stdio::piped())
256        .spawn()
257        .ok()?;
258
259    let (tx, rx) = mpsc::channel();
260    std::thread::spawn(move || {
261        let _ = tx.send(child.wait_with_output());
262    });
263
264    Some(match rx.recv_timeout(Duration::from_secs(2)) {
265        Ok(Ok(output)) => {
266            let out = if output.stderr.is_empty() {
267                output.stdout
268            } else {
269                output.stderr
270            };
271            String::from_utf8(out)
272                .map(|s| s.trim().to_string())
273                .unwrap_or_else(|_| "unknown".to_string())
274        }
275        _ => "unknown".to_string(),
276    })
277}
278
279/// Thread-local log capture for tests. The global logger writes records into a
280/// per-thread sink that is only active inside `capture`, so parallel test
281/// threads never see each other's records and no global lock is needed.
282#[cfg(test)]
283pub(crate) mod capture {
284    use std::cell::RefCell;
285    use std::sync::Once;
286
287    use log::{Level, Log, Metadata, Record};
288
289    thread_local! {
290        static SINK: RefCell<Option<Vec<(Level, String)>>> = const { RefCell::new(None) };
291    }
292
293    struct CaptureLogger;
294
295    impl Log for CaptureLogger {
296        fn enabled(&self, _: &Metadata) -> bool {
297            true
298        }
299        fn log(&self, record: &Record) {
300            SINK.with(|s| {
301                if let Some(buf) = s.borrow_mut().as_mut() {
302                    buf.push((record.level(), record.args().to_string()));
303                }
304            });
305        }
306        fn flush(&self) {}
307    }
308
309    static LOGGER: CaptureLogger = CaptureLogger;
310    static INSTALL: Once = Once::new();
311
312    /// Run `f` and return every log record it emitted on this thread.
313    pub(crate) fn capture<F: FnOnce()>(f: F) -> Vec<(Level, String)> {
314        INSTALL.call_once(|| {
315            // No production test installs a logger, so this wins. If one ever
316            // does, our per-thread sink simply stays empty (set_logger errors).
317            if log::set_logger(&LOGGER).is_ok() {
318                log::set_max_level(log::LevelFilter::Trace);
319            }
320        });
321        SINK.with(|s| *s.borrow_mut() = Some(Vec::new()));
322        f();
323        SINK.with(|s| s.borrow_mut().take().unwrap_or_default())
324    }
325
326    /// True when any captured record matches `level` and contains `needle`.
327    pub(crate) fn has(records: &[(Level, String)], level: Level, needle: &str) -> bool {
328        records
329            .iter()
330            .any(|(lvl, msg)| *lvl == level && msg.contains(needle))
331    }
332}
333
334#[cfg(test)]
335mod tests {
336    use super::*;
337    use std::io::Write;
338
339    #[test]
340    fn rotate_if_needed_renames_large_file() {
341        let dir = tempfile::tempdir().unwrap();
342        let log = dir.path().join("purple.log");
343        let backup = dir.path().join("purple.log.1");
344
345        let mut f = fs::File::create(&log).unwrap();
346        let data = vec![0u8; (MAX_LOG_SIZE + 1) as usize];
347        f.write_all(&data).unwrap();
348        drop(f);
349
350        rotate_if_needed(&log);
351
352        assert!(!log.exists());
353        assert!(backup.exists());
354        assert!(fs::metadata(&backup).unwrap().len() > MAX_LOG_SIZE);
355    }
356
357    #[test]
358    fn rotate_if_needed_leaves_small_file() {
359        let dir = tempfile::tempdir().unwrap();
360        let log = dir.path().join("purple.log");
361
362        fs::write(&log, "small content").unwrap();
363
364        rotate_if_needed(&log);
365
366        assert!(log.exists());
367        assert!(!dir.path().join("purple.log.1").exists());
368    }
369
370    #[test]
371    fn rotate_if_needed_handles_missing_file() {
372        let dir = tempfile::tempdir().unwrap();
373        let log = dir.path().join("purple.log");
374
375        // Should not panic
376        rotate_if_needed(&log);
377    }
378
379    #[test]
380    fn resolve_level_defaults_to_warn() {
381        assert_eq!(resolve_level(false, None), LevelFilter::Warn);
382    }
383
384    #[test]
385    fn resolve_level_verbose_returns_debug() {
386        assert_eq!(resolve_level(true, None), LevelFilter::Debug);
387    }
388
389    #[test]
390    fn resolve_level_env_overrides_verbose() {
391        assert_eq!(resolve_level(false, Some("trace")), LevelFilter::Trace);
392        assert_eq!(resolve_level(true, Some("error")), LevelFilter::Error);
393    }
394
395    #[test]
396    fn resolve_level_ignores_unknown_env_value() {
397        assert_eq!(resolve_level(false, Some("bogus")), LevelFilter::Warn);
398        assert_eq!(resolve_level(true, Some("bogus")), LevelFilter::Debug);
399    }
400
401    #[test]
402    fn epoch_days_to_date_unix_epoch() {
403        // Day 0 = 1970-01-01
404        assert_eq!(epoch_days_to_date(0), (1970, 1, 1));
405    }
406
407    #[test]
408    fn epoch_days_to_date_known_date() {
409        // 2026-04-10 = day 20553
410        assert_eq!(epoch_days_to_date(20553), (2026, 4, 10));
411    }
412
413    #[test]
414    fn epoch_days_to_date_leap_year() {
415        // 2000-02-29 = day 11016
416        assert_eq!(epoch_days_to_date(11016), (2000, 2, 29));
417    }
418
419    #[test]
420    fn format_now_utc_returns_valid_timestamp() {
421        let ts = format_now_utc();
422        // Should be in YYYY-MM-DD HH:MM:SSZ format
423        assert_eq!(ts.len(), 20);
424        assert_eq!(&ts[4..5], "-");
425        assert_eq!(&ts[7..8], "-");
426        assert_eq!(&ts[10..11], " ");
427        assert_eq!(&ts[13..14], ":");
428        assert_eq!(&ts[16..17], ":");
429        assert!(ts.ends_with('Z'));
430    }
431
432    #[test]
433    fn log_path_ends_with_purple_log() {
434        let paths = crate::runtime::env::Paths::new("/home/u");
435        let path = log_path(Some(&paths)).expect("paths present");
436        assert!(path.ends_with(".purple/purple.log"));
437    }
438
439    #[test]
440    fn level_name_defaults_to_warn() {
441        // With no PURPLE_LOG in the injected env, the default is "warn".
442        let env = crate::runtime::env::Env::empty();
443        let name = level_name(false, &env);
444        assert_eq!(name, "warn");
445    }
446
447    #[test]
448    fn write_banner_creates_output() {
449        let info = BannerInfo {
450            version: "0.0.0-test",
451            config_path: "/tmp/config",
452            providers: &["testprov".to_string()],
453            askpass_sources: &["keychain:".to_string()],
454            vault_ssh_info: Some("enabled (addr=https://vault:8200)"),
455            ssh_version: "OpenSSH_9.0",
456            term: "xterm-256color",
457            colorterm: "truecolor",
458            level: "warn",
459            theme: "Purple",
460            hosts: 42,
461            patterns: 3,
462            snippets: 7,
463            proxy_env: "none",
464        };
465
466        // The banner lands in the state directory's log file and names the
467        // resolved category directories, so a support bundle shows where
468        // purple read and wrote.
469        let dir = tempfile::tempdir().unwrap();
470        let state = dir.path().join("state").to_string_lossy().to_string();
471        let paths = crate::runtime::env::Paths::resolve(dir.path(), move |k| {
472            (k == "XDG_STATE_HOME").then(|| state.clone())
473        });
474        std::fs::create_dir_all(paths.state_dir()).unwrap();
475        write_banner(&info, Some(&paths));
476
477        let body = std::fs::read_to_string(paths.log_file()).unwrap();
478        assert!(body.contains("--- purple v0.0.0-test started at "));
479        assert!(body.contains("hosts=42 patterns=3 snippets=7"));
480        assert!(body.contains("providers=testprov"));
481        assert!(body.contains("vault_ssh=enabled (addr=https://vault:8200)"));
482        assert!(
483            body.contains(&format!(
484                "dirs: config={} data={} state={} cache={}",
485                paths.config_dir().display(),
486                paths.data_dir().display(),
487                paths.state_dir().display(),
488                paths.cache_dir().display()
489            )),
490            "{body}"
491        );
492        assert!(body.contains("log_level=warn"));
493
494        let ts = format_now_utc();
495        assert!(ts.ends_with('Z'));
496        assert_eq!(ts.len(), 20);
497    }
498}
purple_ssh/logging.rs

purple_ssh/
logging.rs
