winx_code_agent/
logging.rs

1use std::fs::{self, File, OpenOptions};
2use std::io::{self, Write};
3use std::path::{Path, PathBuf};
4
5#[cfg(unix)]
6use std::os::unix::fs::{DirBuilderExt as _, OpenOptionsExt as _, PermissionsExt as _};
7use time::OffsetDateTime;
8use tracing_appender::non_blocking::{NonBlocking, NonBlockingBuilder, WorkerGuard};
9use tracing_subscriber::filter::filter_fn;
10use tracing_subscriber::layer::SubscriberExt as _;
11use tracing_subscriber::util::SubscriberInitExt as _;
12use tracing_subscriber::Layer as _;
13
14use crate::errors::{Result, WinxError};
15
16/// Keeps the non-blocking usage-log worker alive for the lifetime of the process.
17pub struct LoggingGuard {
18    _usage: Option<WorkerGuard>,
19}
20
21#[derive(Clone, Copy, Debug, Eq, PartialEq)]
22enum UsageRotation {
23    Never,
24    Hourly,
25    Daily,
26}
27
28impl UsageRotation {
29    fn parse(value: Option<&str>) -> Result<Self> {
30        match value.unwrap_or("daily").trim().to_ascii_lowercase().as_str() {
31            "never" => Ok(Self::Never),
32            "hourly" => Ok(Self::Hourly),
33            "daily" | "" => Ok(Self::Daily),
34            other => Err(WinxError::ConfigurationError(format!(
35                "invalid WINX_USAGE_LOG_ROTATION={other:?}; expected `never`, `hourly`, or `daily`"
36            ))),
37        }
38    }
39
40    fn period(self, now: OffsetDateTime) -> Option<String> {
41        let month = u8::from(now.month());
42        match self {
43            Self::Never => None,
44            Self::Daily => Some(format!("{:04}-{month:02}-{:02}", now.year(), now.day())),
45            Self::Hourly => {
46                Some(format!("{:04}-{month:02}-{:02}-{:02}", now.year(), now.day(), now.hour()))
47            }
48        }
49    }
50
51    fn max_files(self, keep_days: usize) -> Option<usize> {
52        if keep_days == 0 || self == Self::Never {
53            return None;
54        }
55        let files_per_day = if self == Self::Hourly { 24 } else { 1 };
56        // Retain one extra file so rotation never dips below the requested
57        // completed-history window while the active file is counted.
58        Some(keep_days.saturating_mul(files_per_day).saturating_add(1))
59    }
60
61    fn valid_period(self, suffix: &str) -> bool {
62        let expected_len = match self {
63            Self::Never => return false,
64            Self::Daily => 10,
65            Self::Hourly => 13,
66        };
67        suffix.len() == expected_len
68            && suffix.bytes().enumerate().all(|(index, byte)| {
69                let dash = index == 4 || index == 7 || (self == Self::Hourly && index == 10);
70                if dash {
71                    byte == b'-'
72                } else {
73                    byte.is_ascii_digit()
74                }
75            })
76    }
77}
78
79/// Minimal secure rolling writer used by the non-blocking tracing worker.
80/// Every file is opened with `O_NOFOLLOW` and mode `0600` on Unix, including
81/// files created after daily/hourly rotation. This avoids relying on the process
82/// umask and closes the short world-readable window a post-open chmod would have.
83struct SecureUsageWriter {
84    base_path: PathBuf,
85    rotation: UsageRotation,
86    keep_days: usize,
87    active_period: Option<String>,
88    active_path: PathBuf,
89    file: File,
90}
91
92impl SecureUsageWriter {
93    fn new(base_path: PathBuf, rotation: UsageRotation, keep_days: usize) -> io::Result<Self> {
94        let parent = log_parent(&base_path);
95        create_log_directory(parent)?;
96        validate_log_file_name(&base_path)?;
97
98        let active_period = rotation.period(OffsetDateTime::now_utc());
99        let active_path = rotated_path(&base_path, active_period.as_deref())?;
100        let file = open_secure_log_file(&active_path)?;
101        let writer = Self { base_path, rotation, keep_days, active_period, active_path, file };
102        writer.prune_old_logs()?;
103        Ok(writer)
104    }
105
106    fn rotate_if_needed(&mut self) -> io::Result<()> {
107        let period = self.rotation.period(OffsetDateTime::now_utc());
108        if period == self.active_period {
109            return Ok(());
110        }
111
112        let path = rotated_path(&self.base_path, period.as_deref())?;
113        let file = open_secure_log_file(&path)?;
114        self.file = file;
115        self.active_path = path;
116        self.active_period = period;
117        self.prune_old_logs()
118    }
119
120    fn prune_old_logs(&self) -> io::Result<()> {
121        let Some(max_files) = self.rotation.max_files(self.keep_days) else {
122            return Ok(());
123        };
124        let parent = log_parent(&self.base_path);
125        let base_name = validate_log_file_name(&self.base_path)?;
126        let prefix = format!("{base_name}.");
127        let mut candidates = Vec::new();
128
129        for entry in fs::read_dir(parent)? {
130            let entry = entry?;
131            let file_type = entry.file_type()?;
132            if !file_type.is_file() || file_type.is_symlink() {
133                continue;
134            }
135            let Some(name) = entry.file_name().to_str().map(ToString::to_string) else {
136                continue;
137            };
138            let Some(period) = name.strip_prefix(&prefix) else {
139                continue;
140            };
141            if self.rotation.valid_period(period) {
142                candidates.push((name, entry.path()));
143            }
144        }
145
146        candidates.sort_by(|left, right| left.0.cmp(&right.0));
147        let remove_count = candidates.len().saturating_sub(max_files);
148        for (_, path) in candidates.into_iter().take(remove_count) {
149            fs::remove_file(path)?;
150        }
151        Ok(())
152    }
153}
154
155impl Write for SecureUsageWriter {
156    fn write(&mut self, buffer: &[u8]) -> io::Result<usize> {
157        self.rotate_if_needed()?;
158        self.file.write(buffer)
159    }
160
161    fn flush(&mut self) -> io::Result<()> {
162        self.file.flush()
163    }
164}
165
166/// Install the stderr subscriber plus an optional JSONL usage-event sink.
167///
168/// `WINX_USAGE_LOG` enables a non-blocking file writer filtered to the
169/// `winx::usage` target. The sink never receives command text or file contents.
170/// While it is active, usage events are not also written to stderr.
171/// Call this only after the optional Landlock domain has been applied so the
172/// writer thread inherits the same filesystem restrictions as every other child.
173pub fn initialize(verbose: bool, debug: bool) -> Result<LoggingGuard> {
174    initialize_inner(verbose, debug, true)
175}
176
177/// Install stderr logging without opening or rotating the usage sink. Offline
178/// inspection commands use this so observing logs cannot mutate them.
179pub fn initialize_without_usage(verbose: bool, debug: bool) -> Result<LoggingGuard> {
180    initialize_inner(verbose, debug, false)
181}
182
183fn initialize_inner(verbose: bool, debug: bool, usage_enabled: bool) -> Result<LoggingGuard> {
184    let level = if debug {
185        tracing::Level::DEBUG
186    } else if verbose {
187        tracing::Level::INFO
188    } else {
189        tracing::Level::WARN
190    };
191    let usage = if usage_enabled { usage_log_writer()? } else { None };
192    let mut filter = tracing_subscriber::EnvFilter::from_default_env().add_directive(level.into());
193    let rust_log = std::env::var("RUST_LOG").ok();
194    if let Some(directive) = stderr_usage_directive(rust_log.as_deref(), usage.is_some()) {
195        // The directive is static and cannot fail to parse.
196        if let Ok(directive) = directive.parse() {
197            filter = filter.add_directive(directive);
198        }
199    }
200    let stderr_json = crate::config::env_text("WINX_LOG_FORMAT")
201        .is_some_and(|format| format.eq_ignore_ascii_case("json"));
202
203    let guard = match (stderr_json, usage) {
204        (true, Some((writer, guard))) => {
205            tracing_subscriber::registry()
206                .with(
207                    tracing_subscriber::fmt::layer()
208                        .json()
209                        .with_ansi(false)
210                        .with_writer(std::io::stderr)
211                        .with_filter(filter),
212                )
213                .with(usage_json_layer(writer))
214                .init();
215            Some(guard)
216        }
217        (false, Some((writer, guard))) => {
218            tracing_subscriber::registry()
219                .with(
220                    tracing_subscriber::fmt::layer()
221                        .with_ansi(true)
222                        .with_writer(std::io::stderr)
223                        .with_filter(filter),
224                )
225                .with(usage_json_layer(writer))
226                .init();
227            Some(guard)
228        }
229        (true, None) => {
230            tracing_subscriber::registry()
231                .with(
232                    tracing_subscriber::fmt::layer()
233                        .json()
234                        .with_ansi(false)
235                        .with_writer(std::io::stderr)
236                        .with_filter(filter),
237                )
238                .init();
239            None
240        }
241        (false, None) => {
242            tracing_subscriber::registry()
243                .with(
244                    tracing_subscriber::fmt::layer()
245                        .with_ansi(true)
246                        .with_writer(std::io::stderr)
247                        .with_filter(filter),
248                )
249                .init();
250            None
251        }
252    };
253    Ok(LoggingGuard { _usage: guard })
254}
255
256/// Decide where `winx::usage` events go on stderr.
257///
258/// Without a usage file, stderr is the only persistent usage sink (journald or
259/// a `tee`'d log), so usage events stay visible at the default WARN level. With
260/// a usage file they are written there only: duplicating them to stderr doubled
261/// log volume and put a synchronous write on the request path. An explicit
262/// `winx::usage` directive in `RUST_LOG` always wins, in both directions.
263fn stderr_usage_directive(rust_log: Option<&str>, usage_file: bool) -> Option<&'static str> {
264    let explicit = rust_log.is_some_and(|value| {
265        value.split(',').any(|directive| {
266            directive.trim().split(['=', '[']).next().map(str::trim) == Some("winx::usage")
267        })
268    });
269    match (explicit, usage_file) {
270        (true, _) => None,
271        (false, true) => Some("winx::usage=off"),
272        (false, false) => Some("winx::usage=info"),
273    }
274}
275
276fn usage_json_layer<S>(writer: NonBlocking) -> impl tracing_subscriber::Layer<S>
277where
278    S: tracing::Subscriber + for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
279{
280    tracing_subscriber::fmt::layer()
281        .json()
282        .with_ansi(false)
283        .with_current_span(false)
284        .with_span_list(false)
285        .with_writer(writer)
286        .with_filter(filter_fn(|metadata| metadata.target() == "winx::usage"))
287}
288
289fn usage_log_writer() -> Result<Option<(NonBlocking, WorkerGuard)>> {
290    let Some(path) = crate::config::env_text("WINX_USAGE_LOG").map(PathBuf::from) else {
291        return Ok(None);
292    };
293    let rotation =
294        UsageRotation::parse(crate::config::env_text("WINX_USAGE_LOG_ROTATION").as_deref())?;
295    let keep_days = parse_keep_days()?;
296    let writer = SecureUsageWriter::new(path.clone(), rotation, keep_days).map_err(|error| {
297        WinxError::ConfigurationError(format!(
298            "cannot open WINX_USAGE_LOG {} securely: {error}",
299            path.display()
300        ))
301    })?;
302    Ok(Some(NonBlockingBuilder::default().thread_name("winx-usage-log").finish(writer)))
303}
304
305fn log_parent(path: &Path) -> &Path {
306    path.parent().filter(|parent| !parent.as_os_str().is_empty()).unwrap_or(Path::new("."))
307}
308
309fn validate_log_file_name(path: &Path) -> io::Result<&str> {
310    path.file_name().and_then(|name| name.to_str()).ok_or_else(|| {
311        io::Error::new(
312            io::ErrorKind::InvalidInput,
313            format!("usage log path must name a UTF-8 file: {}", path.display()),
314        )
315    })
316}
317
318fn rotated_path(base_path: &Path, period: Option<&str>) -> io::Result<PathBuf> {
319    let Some(period) = period else {
320        return Ok(base_path.to_path_buf());
321    };
322    let name = validate_log_file_name(base_path)?;
323    Ok(base_path.with_file_name(format!("{name}.{period}")))
324}
325
326fn create_log_directory(path: &Path) -> io::Result<()> {
327    #[cfg(unix)]
328    {
329        let mut builder = fs::DirBuilder::new();
330        builder.recursive(true).mode(0o700).create(path)
331    }
332    #[cfg(not(unix))]
333    {
334        fs::create_dir_all(path)
335    }
336}
337
338fn open_secure_log_file(path: &Path) -> io::Result<File> {
339    #[cfg(unix)]
340    {
341        let file = OpenOptions::new()
342            .append(true)
343            .create(true)
344            .mode(0o600)
345            .custom_flags(libc::O_NOFOLLOW | libc::O_CLOEXEC)
346            .open(path)?;
347        let metadata = file.metadata()?;
348        if !metadata.is_file() {
349            return Err(io::Error::new(
350                io::ErrorKind::InvalidInput,
351                format!("usage log is not a regular file: {}", path.display()),
352            ));
353        }
354        let mut permissions = metadata.permissions();
355        if permissions.mode() & 0o777 != 0o600 {
356            permissions.set_mode(0o600);
357            file.set_permissions(permissions)?;
358        }
359        Ok(file)
360    }
361    #[cfg(not(unix))]
362    {
363        let file = OpenOptions::new().append(true).create(true).open(path)?;
364        if !file.metadata()?.is_file() {
365            return Err(io::Error::new(
366                io::ErrorKind::InvalidInput,
367                format!("usage log is not a regular file: {}", path.display()),
368            ));
369        }
370        Ok(file)
371    }
372}
373
374fn parse_keep_days() -> Result<usize> {
375    let Some(raw) = crate::config::env_text("WINX_USAGE_LOG_KEEP_DAYS") else {
376        return Ok(7);
377    };
378    let days = raw.parse::<usize>().map_err(|error| {
379        WinxError::ConfigurationError(format!("invalid WINX_USAGE_LOG_KEEP_DAYS={raw:?}: {error}"))
380    })?;
381    if days > 3_650 {
382        return Err(WinxError::ConfigurationError(
383            "WINX_USAGE_LOG_KEEP_DAYS must be between 0 and 3650".to_string(),
384        ));
385    }
386    Ok(days)
387}
388
389#[cfg(test)]
390mod tests {
391    #![allow(clippy::unwrap_used)]
392
393    #[cfg(unix)]
394    use super::SecureUsageWriter;
395    use super::UsageRotation;
396    #[cfg(unix)]
397    use std::io::Write as _;
398
399    #[test]
400    fn usage_events_reach_stderr_only_without_a_usage_file() {
401        use super::stderr_usage_directive as directive;
402
403        assert_eq!(directive(None, false), Some("winx::usage=info"));
404        assert_eq!(directive(None, true), Some("winx::usage=off"));
405        // Broader targets do not count as asking for usage events on stderr.
406        assert_eq!(directive(Some("winx=debug,info"), true), Some("winx::usage=off"));
407        assert_eq!(directive(Some("winx::usage_extra=info"), true), Some("winx::usage=off"));
408        // An explicit directive is left to RUST_LOG, whichever way it points.
409        assert_eq!(directive(Some("warn, winx::usage=info"), true), None);
410        assert_eq!(directive(Some("winx::usage"), true), None);
411        assert_eq!(directive(Some("winx::usage[span]=debug"), true), None);
412        assert_eq!(directive(Some("winx::usage=off"), false), None);
413    }
414
415    #[test]
416    fn usage_rotation_retention_is_bounded_and_explicit() {
417        assert!(matches!(UsageRotation::parse(None), Ok(UsageRotation::Daily)));
418        assert_eq!(UsageRotation::Daily.max_files(7), Some(8));
419        assert_eq!(UsageRotation::Hourly.max_files(2), Some(49));
420        assert_eq!(UsageRotation::Never.max_files(7), None);
421        assert_eq!(UsageRotation::Daily.max_files(0), None);
422    }
423
424    #[cfg(unix)]
425    #[test]
426    fn usage_files_are_private_for_initial_and_rotated_names() {
427        use std::os::unix::fs::PermissionsExt as _;
428
429        for rotation in [UsageRotation::Never, UsageRotation::Daily, UsageRotation::Hourly] {
430            let root = tempfile::tempdir().unwrap();
431            let nested = root.path().join("private/state");
432            let base = nested.join("usage.jsonl");
433            let mut writer = SecureUsageWriter::new(base, rotation, 1).unwrap();
434            writer.write_all(b"{}\n").unwrap();
435            writer.flush().unwrap();
436
437            let mode = writer.active_path.metadata().unwrap().permissions().mode() & 0o777;
438            assert_eq!(mode, 0o600, "{}", writer.active_path.display());
439            let directory_mode = nested.metadata().unwrap().permissions().mode() & 0o777;
440            assert_eq!(directory_mode, 0o700, "{}", nested.display());
441
442            if rotation != UsageRotation::Never {
443                let rotated_path = writer.active_path.clone();
444                std::fs::remove_file(&rotated_path).unwrap();
445                writer.active_period = Some("1970-01-01-00".to_string());
446                writer.write_all(b"rotated\n").unwrap();
447                writer.flush().unwrap();
448                let rotated_mode = rotated_path.metadata().unwrap().permissions().mode() & 0o777;
449                assert_eq!(rotated_mode, 0o600, "{}", rotated_path.display());
450            }
451        }
452    }
453
454    #[cfg(unix)]
455    #[test]
456    fn existing_usage_file_is_tightened_and_symlink_is_rejected() {
457        use std::os::unix::fs::{symlink, PermissionsExt as _};
458
459        let root = tempfile::tempdir().unwrap();
460        let existing = root.path().join("existing.jsonl");
461        std::fs::write(&existing, b"old\n").unwrap();
462        std::fs::set_permissions(&existing, std::fs::Permissions::from_mode(0o644)).unwrap();
463        let writer = SecureUsageWriter::new(existing.clone(), UsageRotation::Never, 0).unwrap();
464        let mode = writer.active_path.metadata().unwrap().permissions().mode() & 0o777;
465        assert_eq!(mode, 0o600);
466        drop(writer);
467
468        let target = root.path().join("target.jsonl");
469        std::fs::write(&target, b"target\n").unwrap();
470        let link = root.path().join("link.jsonl");
471        symlink(&target, &link).unwrap();
472        assert!(SecureUsageWriter::new(link, UsageRotation::Never, 0).is_err());
473    }
474}
winx_code_agent/logging.rs

winx_code_agent/
logging.rs
