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        if meta.len() > MAX_LOG_SIZE {
27            let backup = path.with_file_name("purple.log.1");
28            let _ = fs::rename(path, backup);
29        }
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        if let Err(e) = CombinedLogger::init(loggers) {
92            eprintln!("{}", crate::messages::logging::init_failed(&e));
93        }
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    banner.push_str(&format!("    log_level={}\n", info.level));
205
206    // Note: banner lines use \x20 (space) prefix to prevent the Rust string
207    // continuation from collapsing leading whitespace. This is a rustfmt-safe
208    // idiom for multi-line format strings with indentation.
209
210    // Non-fatal: banner write failure does not affect logging
211    let _ = file.write_all(banner.as_bytes());
212}
213
214/// Return the effective log level name as a lowercase string.
215pub fn level_name(verbose: bool, env: &crate::runtime::env::Env) -> String {
216    resolve_level(verbose, env.var("PURPLE_LOG"))
217        .as_str()
218        .to_lowercase()
219}
220
221/// Detect SSH version by running `ssh -V` (output goes to stderr).
222/// Uses a 2-second timeout via mpsc channel to avoid hanging startup
223/// if the ssh binary is broken or on a slow filesystem.
224///
225/// On timeout, the spawned thread and child process continue running until
226/// `ssh -V` exits naturally. This is acceptable because `ssh -V` is
227/// near-instant and this only runs once at startup.
228pub fn detect_ssh_version() -> String {
229    use std::sync::mpsc;
230    use std::time::Duration;
231
232    let child = std::process::Command::new("ssh")
233        .arg("-V")
234        .stdout(std::process::Stdio::piped())
235        .stderr(std::process::Stdio::piped())
236        .spawn();
237
238    let Ok(child) = child else {
239        eprintln!("{}", crate::messages::logging::SSH_VERSION_FAILED);
240        return "unknown".to_string();
241    };
242
243    let (tx, rx) = mpsc::channel();
244    std::thread::spawn(move || {
245        let _ = tx.send(child.wait_with_output());
246    });
247
248    match rx.recv_timeout(Duration::from_secs(2)) {
249        Ok(Ok(output)) => {
250            let out = if output.stderr.is_empty() {
251                output.stdout
252            } else {
253                output.stderr
254            };
255            String::from_utf8(out)
256                .map(|s| s.trim().to_string())
257                .unwrap_or_else(|_| "unknown".to_string())
258        }
259        _ => "unknown".to_string(),
260    }
261}
262
263/// Thread-local log capture for tests. The global logger writes records into a
264/// per-thread sink that is only active inside `capture`, so parallel test
265/// threads never see each other's records and no global lock is needed.
266#[cfg(test)]
267pub(crate) mod capture {
268    use std::cell::RefCell;
269    use std::sync::Once;
270
271    use log::{Level, Log, Metadata, Record};
272
273    thread_local! {
274        static SINK: RefCell<Option<Vec<(Level, String)>>> = const { RefCell::new(None) };
275    }
276
277    struct CaptureLogger;
278
279    impl Log for CaptureLogger {
280        fn enabled(&self, _: &Metadata) -> bool {
281            true
282        }
283        fn log(&self, record: &Record) {
284            SINK.with(|s| {
285                if let Some(buf) = s.borrow_mut().as_mut() {
286                    buf.push((record.level(), record.args().to_string()));
287                }
288            });
289        }
290        fn flush(&self) {}
291    }
292
293    static LOGGER: CaptureLogger = CaptureLogger;
294    static INSTALL: Once = Once::new();
295
296    /// Run `f` and return every log record it emitted on this thread.
297    pub(crate) fn capture<F: FnOnce()>(f: F) -> Vec<(Level, String)> {
298        INSTALL.call_once(|| {
299            // No production test installs a logger, so this wins. If one ever
300            // does, our per-thread sink simply stays empty (set_logger errors).
301            if log::set_logger(&LOGGER).is_ok() {
302                log::set_max_level(log::LevelFilter::Trace);
303            }
304        });
305        SINK.with(|s| *s.borrow_mut() = Some(Vec::new()));
306        f();
307        SINK.with(|s| s.borrow_mut().take().unwrap_or_default())
308    }
309
310    /// True when any captured record matches `level` and contains `needle`.
311    pub(crate) fn has(records: &[(Level, String)], level: Level, needle: &str) -> bool {
312        records
313            .iter()
314            .any(|(lvl, msg)| *lvl == level && msg.contains(needle))
315    }
316}
317
318#[cfg(test)]
319mod tests {
320    use super::*;
321    use std::io::Write;
322
323    #[test]
324    fn rotate_if_needed_renames_large_file() {
325        let dir = tempfile::tempdir().unwrap();
326        let log = dir.path().join("purple.log");
327        let backup = dir.path().join("purple.log.1");
328
329        let mut f = fs::File::create(&log).unwrap();
330        let data = vec![0u8; (MAX_LOG_SIZE + 1) as usize];
331        f.write_all(&data).unwrap();
332        drop(f);
333
334        rotate_if_needed(&log);
335
336        assert!(!log.exists());
337        assert!(backup.exists());
338        assert!(fs::metadata(&backup).unwrap().len() > MAX_LOG_SIZE);
339    }
340
341    #[test]
342    fn rotate_if_needed_leaves_small_file() {
343        let dir = tempfile::tempdir().unwrap();
344        let log = dir.path().join("purple.log");
345
346        fs::write(&log, "small content").unwrap();
347
348        rotate_if_needed(&log);
349
350        assert!(log.exists());
351        assert!(!dir.path().join("purple.log.1").exists());
352    }
353
354    #[test]
355    fn rotate_if_needed_handles_missing_file() {
356        let dir = tempfile::tempdir().unwrap();
357        let log = dir.path().join("purple.log");
358
359        // Should not panic
360        rotate_if_needed(&log);
361    }
362
363    #[test]
364    fn resolve_level_defaults_to_warn() {
365        assert_eq!(resolve_level(false, None), LevelFilter::Warn);
366    }
367
368    #[test]
369    fn resolve_level_verbose_returns_debug() {
370        assert_eq!(resolve_level(true, None), LevelFilter::Debug);
371    }
372
373    #[test]
374    fn resolve_level_env_overrides_verbose() {
375        assert_eq!(resolve_level(false, Some("trace")), LevelFilter::Trace);
376        assert_eq!(resolve_level(true, Some("error")), LevelFilter::Error);
377    }
378
379    #[test]
380    fn resolve_level_ignores_unknown_env_value() {
381        assert_eq!(resolve_level(false, Some("bogus")), LevelFilter::Warn);
382        assert_eq!(resolve_level(true, Some("bogus")), LevelFilter::Debug);
383    }
384
385    #[test]
386    fn epoch_days_to_date_unix_epoch() {
387        // Day 0 = 1970-01-01
388        assert_eq!(epoch_days_to_date(0), (1970, 1, 1));
389    }
390
391    #[test]
392    fn epoch_days_to_date_known_date() {
393        // 2026-04-10 = day 20553
394        assert_eq!(epoch_days_to_date(20553), (2026, 4, 10));
395    }
396
397    #[test]
398    fn epoch_days_to_date_leap_year() {
399        // 2000-02-29 = day 11016
400        assert_eq!(epoch_days_to_date(11016), (2000, 2, 29));
401    }
402
403    #[test]
404    fn format_now_utc_returns_valid_timestamp() {
405        let ts = format_now_utc();
406        // Should be in YYYY-MM-DD HH:MM:SSZ format
407        assert_eq!(ts.len(), 20);
408        assert_eq!(&ts[4..5], "-");
409        assert_eq!(&ts[7..8], "-");
410        assert_eq!(&ts[10..11], " ");
411        assert_eq!(&ts[13..14], ":");
412        assert_eq!(&ts[16..17], ":");
413        assert!(ts.ends_with('Z'));
414    }
415
416    #[test]
417    fn log_path_ends_with_purple_log() {
418        let paths = crate::runtime::env::Paths::new("/home/u");
419        let path = log_path(Some(&paths)).expect("paths present");
420        assert!(path.ends_with(".purple/purple.log"));
421    }
422
423    #[test]
424    fn level_name_defaults_to_warn() {
425        // With no PURPLE_LOG in the injected env, the default is "warn".
426        let env = crate::runtime::env::Env::empty();
427        let name = level_name(false, &env);
428        assert_eq!(name, "warn");
429    }
430
431    #[test]
432    fn write_banner_creates_output() {
433        // write_banner uses log_path() which returns ~/.purple/purple.log,
434        // so we test the banner formatting logic via struct construction
435        let info = BannerInfo {
436            version: "0.0.0-test",
437            config_path: "/tmp/config",
438            providers: &["testprov".to_string()],
439            askpass_sources: &["keychain:".to_string()],
440            vault_ssh_info: Some("enabled (addr=https://vault:8200)"),
441            ssh_version: "OpenSSH_9.0",
442            term: "xterm-256color",
443            colorterm: "truecolor",
444            level: "warn",
445            theme: "Purple",
446            hosts: 42,
447            patterns: 3,
448            snippets: 7,
449            proxy_env: "none",
450        };
451
452        // Verify the banner struct fields are accessible and well-formed
453        assert_eq!(info.version, "0.0.0-test");
454        assert_eq!(info.providers.len(), 1);
455        assert!(info.vault_ssh_info.is_some());
456        assert_eq!(info.theme, "Purple");
457        assert_eq!(info.hosts, 42);
458        assert_eq!(info.snippets, 7);
459        assert_eq!(info.proxy_env, "none");
460
461        // We can't easily redirect log_path() in a unit test, but we can
462        // verify the format_now_utc helper used by write_banner
463        let ts = format_now_utc();
464        assert!(ts.ends_with('Z'));
465        assert_eq!(ts.len(), 20);
466    }
467}
purple_ssh/logging.rs

purple_ssh/
logging.rs
