返回 CodeWhale
runtime_log.rs
根目录 / crates / tui / src / runtime_log.rs
1 //! TUI runtime logging. Initializes a `tracing-subscriber` that writes to a
2 //! per-process file under `~/.codewhale/logs/tui-YYYY-MM-DD-PID.log`, and (on
3 //! Unix and Windows) redirects the process's `stderr` handle/fd to that same
4 //! file for the lifetime of the alt-screen TUI.
5 //!
6 //! Why this exists:
7 //!
8 //! The TUI runs inside an alt-screen buffer drawn by `ratatui` using an
9 //! incremental diff renderer. The renderer assumes nothing else is writing
10 //! to the terminal — its internal "current cells" model is the only source
11 //! of truth for what's on screen. If anything emits raw bytes to stdout or
12 //! stderr while the alt-screen is active (an `eprintln!` from a sub-agent,
13 //! a `tracing` warning that defaulted to `stderr`, a panic message, a
14 //! third-party crate's verbose output, …) those bytes land in the alt-screen
15 //! buffer at the current cursor position, scroll the buffer up, and leave
16 //! the renderer's model out of sync with reality. The visible symptom is
17 //! "scroll demon": the TUI content drifts down, leaving a band of blank
18 //! rows above the header. This was the regression in issue #1085 (fixed in
19 //! v0.8.18 by adding a viewport-reset path) and re-surfaced in v0.8.27
20 //! when the flicker fix dropped the `\x1b[2J\x1b[3J` deep-clear that had
21 //! been masking the underlying leak.
22 //!
23 //! Defence-in-depth:
24 //! 1. A `tracing-subscriber` writes formatted logs to
25 //! `~/.codewhale/logs/tui-YYYY-MM-DD-PID.log` so `tracing::warn!` /
26 //! `tracing::error!` calls go somewhere observable instead of
27 //! disappearing into the void (the TUI previously had no global
28 //! subscriber, so contributors reached for `eprintln!`).
29 //! 2. On Unix and Windows the process's stderr handle/fd is redirected to
30 //! the same log file for the lifetime of `TuiLogGuard`. Any raw stderr
31 //! write — ours, a dependency's, a panic message — lands in the log
32 //! file instead of the alt-screen. The guard restores the original
33 //! stderr handle/fd on drop so post-TUI shutdown messages still reach
34 //! the user's terminal.
35 //! 3. Crate-level `#![deny(clippy::print_stderr, clippy::print_stdout)]`
36 //! on the TUI runtime modules forbids new `eprintln!` / `println!`
37 //! calls at compile time. CLI-output paths (`main.rs` eval, init,
38 //! `runtime_api::print_*`, `logging::info`/`warn`) keep their existing
39 //! prints via `#[allow(clippy::print_stderr)]` because they run before
40 //! the alt-screen is entered.
41
42 use std::fs::{self, File, OpenOptions};
43 use std::path::{Path, PathBuf};
44 use std::time::{Duration, SystemTime};
45
46 use anyhow::{Context, Result};
47 use tracing_subscriber::{EnvFilter, fmt, prelude::*};
48
49 const DEFAULT_LOG_RETENTION_DAYS: u64 = 7;
50 const LOG_RETENTION_ENV: &str = "DEEPSEEK_LOG_RETENTION_DAYS";
51 const SECONDS_PER_DAY: u64 = 24 * 60 * 60;
52
53 /// Owns the active tracing subscriber and (on Unix/Windows) a saved copy of
54 /// the original `stderr` handle/fd so it can be restored on drop. Dropped when
55 /// the TUI exits the alt-screen.
56 pub struct TuiLogGuard {
57 #[cfg(unix)]
58 saved_stderr_fd: Option<libc::c_int>,
59 #[cfg(windows)]
60 saved_stderr_handle: Option<windows::Win32::Foundation::HANDLE>,
61 #[cfg(windows)]
62 redirected_stderr_handle: Option<windows::Win32::Foundation::HANDLE>,
63 _file: File,
64 }
65
66 #[cfg(unix)]
67 impl Drop for TuiLogGuard {
68 fn drop(&mut self) {
69 if let Some(saved) = self.saved_stderr_fd.take() {
70 // SAFETY: `saved` came from `libc::dup` of the original stderr
71 // fd in `init`; calling `dup2` to restore it is the standard
72 // pairing. If `dup2` fails we just leak the saved fd — the
73 // process is exiting anyway.
74 unsafe {
75 let _ = libc::dup2(saved, libc::STDERR_FILENO);
76 let _ = libc::close(saved);
77 }
78 }
79 }
80 }
81
82 #[cfg(windows)]
83 impl Drop for TuiLogGuard {
84 fn drop(&mut self) {
85 if let Some(handle) = self.saved_stderr_handle.take() {
86 // SAFETY: `handle` is owned here via take; Drop runs once.
87 unsafe {
88 let _ = windows::Win32::System::Console::SetStdHandle(
89 windows::Win32::System::Console::STD_ERROR_HANDLE,
90 handle,
91 );
92 }
93 }
94 // Close the duplicated handle that was serving as the redirected
95 // stderr target. This is safe because `SetStdHandle` above already
96 // restored the original handle, so nothing references this one.
97 if let Some(dup) = self.redirected_stderr_handle.take() {
98 // SAFETY: `dup` is owned here via take; nothing references it.
99 unsafe {
100 let _ = windows::Win32::Foundation::CloseHandle(dup);
101 }
102 }
103 }
104 }
105
106 #[cfg(not(any(unix, windows)))]
107 impl Drop for TuiLogGuard {
108 fn drop(&mut self) {}
109 }
110
111 /// Initialize the TUI logging subsystem. Idempotent across re-entry by way
112 /// of `set_default` — if a global subscriber is already set we still install
113 /// the stderr redirect.
114 ///
115 /// Returns a guard that must outlive the alt-screen session. Drop it after
116 /// `LeaveAlternateScreen` so any shutdown messages reach the user.
117 pub fn init() -> Result<TuiLogGuard> {
118 let log_dir = log_directory().context("could not resolve TUI log directory")?;
119 fs::create_dir_all(&log_dir)
120 .with_context(|| format!("failed to create {}", log_dir.display()))?;
121 let _ = prune_old_logs(&log_dir, log_retention_days());
122
123 let date = chrono::Local::now().format("%Y-%m-%d").to_string();
124 let log_path = log_dir.join(log_file_name(&date, std::process::id()));
125
126 let file = open_log_file(&log_path)
127 .with_context(|| format!("failed to open {}", log_path.display()))?;
128
129 // The tracing-subscriber consumes a clone of the file handle for its
130 // writer. We keep our own handle for the dup2 redirect below — we need
131 // the same on-disk file but a separate fd so the subscriber's writes
132 // and the raw-stderr writes don't fight over the same kernel offset.
133 let subscriber_file = file
134 .try_clone()
135 .context("failed to clone log file handle for subscriber")?;
136
137 let env_filter = EnvFilter::try_from_default_env()
138 .or_else(|_| EnvFilter::try_new("info"))
139 .unwrap_or_else(|_| EnvFilter::new("info"));
140
141 let log_path_clone = log_path.clone();
142 let subscriber = tracing_subscriber::registry().with(env_filter).with(
143 fmt::layer()
144 .with_writer(move || -> Box<dyn std::io::Write + Send> {
145 // Clone the file handle for each write. If clone fails (fd exhaustion),
146 // fall back to reopening the same path, or ultimately stderr.
147 match subscriber_file.try_clone() {
148 Ok(f) => Box::new(f),
149 Err(e) => {
150 tracing::warn!("Failed to clone log file handle: {e}, reopening");
151 match open_log_file(&log_path_clone) {
152 Ok(f) => Box::new(f),
153 Err(_) => Box::new(std::io::stderr()),
154 }
155 }
156 }
157 })
158 .with_ansi(false)
159 .with_target(true)
160 .with_thread_ids(false),
161 );
162
163 // Best-effort: if a subscriber is already set (e.g., re-entry, or a
164 // host process installed one), we skip ours rather than panic. The
165 // stderr redirect below still happens.
166 let _ = tracing::subscriber::set_global_default(subscriber);
167
168 #[cfg(unix)]
169 let saved_stderr_fd = redirect_stderr_to(&file).ok();
170 #[cfg(windows)]
171 let (saved_stderr_handle, redirected_stderr_handle) = match redirect_stderr_to(&file) {
172 Ok((saved, dup)) => (Some(saved), Some(dup)),
173 Err(e) => {
174 tracing::warn!("Failed to redirect stderr to log file: {e}");
175 (None, None)
176 }
177 };
178
179 Ok(TuiLogGuard {
180 #[cfg(unix)]
181 saved_stderr_fd,
182 #[cfg(windows)]
183 saved_stderr_handle,
184 #[cfg(windows)]
185 redirected_stderr_handle,
186 _file: file,
187 })
188 }
189
190 /// Open (creating if needed) the per-process log for append. Logs can hold
191 /// prompts and paths, so on Unix the file is owner-only: created 0600, an
192 /// existing file is tightened to 0600, and a symlink at the log path is
193 /// refused (`O_NOFOLLOW`) instead of followed to wherever it points.
194 fn open_log_file(path: &Path) -> std::io::Result<std::fs::File> {
195 let mut options = OpenOptions::new();
196 options.create(true).append(true);
197 #[cfg(unix)]
198 {
199 use std::os::unix::fs::{OpenOptionsExt as _, PermissionsExt as _};
200 options
201 .mode(0o600)
202 .custom_flags(libc::O_NOFOLLOW | libc::O_CLOEXEC);
203 let file = options.open(path)?;
204 file.set_permissions(std::fs::Permissions::from_mode(0o600))?;
205 Ok(file)
206 }
207 #[cfg(not(unix))]
208 {
209 options.open(path)
210 }
211 }
212
213 pub(crate) fn log_directory() -> Option<PathBuf> {
214 // $CODEWHALE_HOME is a hard override of the base data directory
215 // (docs/CONFIGURATION.md): when SET, logs live under it and we do NOT fall
216 // back to the legacy ~/.deepseek path — silent fallback would defeat the
217 // isolation the override promises (CI, containers, test harnesses). We
218 // check the env var directly rather than codewhale_home()'s Ok/Err because
219 // that helper succeeds (returns $HOME/.codewhale) even when the override is
220 // unset, which would short-circuit the legacy fallback below.
221 if let Some(home) = codewhale_paths::codewhale_home_override().ok().flatten() {
222 return Some(home.join("logs"));
223 }
224 let resolve = |base: PathBuf| -> Option<PathBuf> {
225 let primary = base.join(".codewhale").join("logs");
226 if primary.exists() {
227 return Some(primary);
228 }
229 let legacy = base.join(".deepseek").join("logs");
230 if legacy.exists() {
231 return Some(legacy);
232 }
233 Some(primary)
234 };
235 codewhale_paths::user_home().and_then(resolve)
236 }
237
238 fn log_file_name(date: &str, pid: u32) -> String {
239 format!("tui-{date}-{pid}.log")
240 }
241
242 fn log_retention_days() -> u64 {
243 std::env::var(LOG_RETENTION_ENV)
244 .ok()
245 .and_then(|raw| raw.trim().parse::<u64>().ok())
246 .filter(|days| *days > 0)
247 .unwrap_or(DEFAULT_LOG_RETENTION_DAYS)
248 }
249
250 fn prune_old_logs(log_dir: &Path, retention_days: u64) -> std::io::Result<usize> {
251 let retention = Duration::from_secs(retention_days.saturating_mul(SECONDS_PER_DAY));
252 let cutoff = SystemTime::now()
253 .checked_sub(retention)
254 .unwrap_or(SystemTime::UNIX_EPOCH);
255 let mut removed = 0usize;
256
257 for entry in fs::read_dir(log_dir)? {
258 let entry = entry?;
259 if !is_tui_log_file_name(&entry.file_name()) {
260 continue;
261 }
262 let metadata = match entry.metadata() {
263 Ok(metadata) if metadata.is_file() => metadata,
264 _ => continue,
265 };
266 let modified = match metadata.modified() {
267 Ok(modified) => modified,
268 Err(_) => continue,
269 };
270 if modified < cutoff && fs::remove_file(entry.path()).is_ok() {
271 removed += 1;
272 }
273 }
274
275 Ok(removed)
276 }
277
278 fn is_tui_log_file_name(file_name: &std::ffi::OsStr) -> bool {
279 file_name
280 .to_str()
281 .is_some_and(|name| name.starts_with("tui-") && name.ends_with(".log"))
282 }
283
284 #[cfg(unix)]
285 fn redirect_stderr_to(file: &File) -> Result<libc::c_int> {
286 use std::os::fd::AsRawFd;
287 let target = file.as_raw_fd();
288 // SAFETY: `libc::dup` and `libc::dup2` are the documented fd-management
289 // primitives. We save the current stderr fd before reassigning so the
290 // guard can restore it on drop.
291 unsafe {
292 let saved = libc::dup(libc::STDERR_FILENO);
293 if saved < 0 {
294 return Err(
295 anyhow::Error::from(std::io::Error::last_os_error()).context("dup(STDERR_FILENO)")
296 );
297 }
298 if libc::dup2(target, libc::STDERR_FILENO) < 0 {
299 let err = std::io::Error::last_os_error();
300 let _ = libc::close(saved);
301 return Err(anyhow::Error::from(err).context("dup2(log_file, STDERR_FILENO)"));
302 }
303 Ok(saved)
304 }
305 }
306
307 #[cfg(windows)]
308 fn redirect_stderr_to(
309 file: &File,
310 ) -> Result<(
311 windows::Win32::Foundation::HANDLE,
312 windows::Win32::Foundation::HANDLE,
313 )> {
314 use std::os::windows::io::AsRawHandle;
315 use windows::Win32::Foundation::{CloseHandle, DUPLICATE_SAME_ACCESS, DuplicateHandle, HANDLE};
316 use windows::Win32::System::Console::{GetStdHandle, STD_ERROR_HANDLE, SetStdHandle};
317 use windows::Win32::System::Threading::GetCurrentProcess;
318
319 // SAFETY: GetStdHandle is always available; returns INVALID_HANDLE_VALUE
320 // on failure or null-like handles for console-less processes.
321 let saved =
322 unsafe { GetStdHandle(STD_ERROR_HANDLE) }.context("GetStdHandle(STD_ERROR_HANDLE)")?;
323 if saved.is_invalid() {
324 return Err(anyhow::anyhow!("GetStdHandle(STD_ERROR_HANDLE) failed"));
325 }
326
327 // Duplicate the file handle so the redirected stderr owns an
328 // independent HANDLE — mirroring the Unix path's `libc::dup`.
329 // Without this, `_file` and stderr would alias the same HANDLE;
330 // a rogue `CloseHandle` on stderr would silently invalidate `_file`.
331 let raw = HANDLE(file.as_raw_handle());
332 // SAFETY: pseudo-handle; no preconditions.
333 let process = unsafe { GetCurrentProcess() };
334 let mut dup = HANDLE::default();
335 // SAFETY: `file` and `dup` are live; pseudo-handle needs no close.
336 unsafe {
337 DuplicateHandle(
338 process,
339 raw,
340 process,
341 &mut dup,
342 0,
343 false,
344 DUPLICATE_SAME_ACCESS,
345 )
346 .context("DuplicateHandle for stderr redirect")?;
347 }
348
349 // SAFETY: SetStdHandle redirects stderr to the duplicated handle.
350 // We save the original handle so the guard can restore it on drop.
351 unsafe {
352 if let Err(e) = SetStdHandle(STD_ERROR_HANDLE, dup) {
353 let _ = CloseHandle(dup);
354 return Err(anyhow::anyhow!(
355 "SetStdHandle(STD_ERROR_HANDLE) failed: {e}"
356 ));
357 }
358 }
359 Ok((saved, dup))
360 }
361
362 #[cfg(test)]
363 mod tests {
364 use super::*;
365 use std::fs::FileTimes;
366
367 #[cfg(unix)]
368 #[test]
369 fn log_file_is_owner_only_and_refuses_symlinks() {
370 use std::io::Write as _;
371 use std::os::unix::fs::{PermissionsExt as _, symlink};
372 let tmp = tempfile::TempDir::new().expect("temporary dir");
373 let mode = |path: &Path| {
374 std::fs::metadata(path)
375 .expect("metadata")
376 .permissions()
377 .mode()
378 & 0o777
379 };
380
381 let fresh = tmp.path().join("fresh.log");
382 open_log_file(&fresh)
383 .expect("create")
384 .write_all(b"one\n")
385 .expect("write");
386 assert_eq!(mode(&fresh), 0o600);
387
388 // An existing world-readable log is tightened, and stays appended to.
389 let old = tmp.path().join("old.log");
390 std::fs::write(&old, "before\n").expect("seed");
391 std::fs::set_permissions(&old, std::fs::Permissions::from_mode(0o644)).expect("chmod");
392 open_log_file(&old)
393 .expect("reopen")
394 .write_all(b"after\n")
395 .expect("write");
396 assert_eq!(mode(&old), 0o600);
397 assert_eq!(
398 std::fs::read_to_string(&old).expect("read"),
399 "before\nafter\n"
400 );
401
402 // A symlink planted at the log path is not followed.
403 let target = tmp.path().join("target.txt");
404 std::fs::write(&target, "keep").expect("target");
405 std::fs::set_permissions(&target, std::fs::Permissions::from_mode(0o644)).expect("chmod");
406 let link = tmp.path().join("link.log");
407 symlink(&target, &link).expect("symlink");
408 assert!(open_log_file(&link).is_err());
409 assert_eq!(std::fs::read_to_string(&target).expect("read"), "keep");
410 assert_eq!(mode(&target), 0o644);
411 }
412
413 #[test]
414 fn whitespace_home_override_is_consistent_across_tui_state_entry_points() {
415 let _lock = crate::test_support::lock_test_env();
416 let tmp = tempfile::TempDir::new().expect("temporary root");
417 let home = tmp.path().join("home");
418 let userprofile = tmp.path().join("userprofile");
419 let _home = crate::test_support::EnvVarGuard::set("HOME", &home);
420 let _userprofile = crate::test_support::EnvVarGuard::set("USERPROFILE", &userprofile);
421 let _codewhale_home = crate::test_support::EnvVarGuard::set("CODEWHALE_HOME", " \t ");
422 let _config_path = crate::test_support::EnvVarGuard::remove("CODEWHALE_CONFIG_PATH");
423 let _legacy_config_path = crate::test_support::EnvVarGuard::remove("DEEPSEEK_CONFIG_PATH");
424 let primary = home.join(".codewhale");
425
426 assert_eq!(crate::config::effective_home_dir(), Some(home.clone()));
427 assert_eq!(
428 crate::config::workspace_trust_config_candidate_paths(),
429 vec![
430 primary.join("config.toml"),
431 home.join(".deepseek").join("config.toml")
432 ]
433 );
434 assert_eq!(log_directory(), Some(primary.join("logs")));
435 assert_eq!(
436 crate::automation_manager::default_automations_dir(),
437 primary.join("automations")
438 );
439 assert_eq!(
440 crate::session_manager::default_sessions_dir().expect("session directory"),
441 primary.join("sessions")
442 );
443 }
444
445 fn set_modified(path: &Path, modified: SystemTime) {
446 let file = OpenOptions::new().write(true).open(path).unwrap();
447 file.set_times(FileTimes::new().set_modified(modified))
448 .unwrap();
449 }
450
451 #[test]
452 fn log_directory_prefers_home() {
453 let _lock = crate::test_support::lock_test_env();
454 let tmp = tempfile::TempDir::new().unwrap();
455 let prev_home = std::env::var_os("HOME");
456 let prev_userprofile = std::env::var_os("USERPROFILE");
457 // SAFETY: serialised by lock_test_env.
458 unsafe {
459 std::env::set_var("HOME", tmp.path());
460 std::env::set_var("USERPROFILE", "");
461 }
462
463 let resolved = log_directory().expect("log_directory should resolve");
464 assert_eq!(resolved, tmp.path().join(".codewhale").join("logs"));
465
466 // SAFETY: cleanup under the same lock.
467 unsafe {
468 match prev_home {
469 Some(v) => std::env::set_var("HOME", v),
470 None => std::env::remove_var("HOME"),
471 }
472 match prev_userprofile {
473 Some(v) => std::env::set_var("USERPROFILE", v),
474 None => std::env::remove_var("USERPROFILE"),
475 }
476 }
477 }
478
479 #[test]
480 fn log_directory_uses_existing_legacy_deepseek_logs() {
481 let _lock = crate::test_support::lock_test_env();
482 let tmp = tempfile::TempDir::new().unwrap();
483 let legacy = tmp.path().join(".deepseek").join("logs");
484 fs::create_dir_all(&legacy).unwrap();
485 let prev_home = std::env::var_os("HOME");
486 let prev_userprofile = std::env::var_os("USERPROFILE");
487 // SAFETY: serialised by lock_test_env.
488 unsafe {
489 std::env::set_var("HOME", tmp.path());
490 std::env::set_var("USERPROFILE", "");
491 }
492
493 let resolved = log_directory().expect("log_directory should resolve");
494 assert_eq!(resolved, legacy);
495
496 // SAFETY: cleanup under the same lock.
497 unsafe {
498 match prev_home {
499 Some(v) => std::env::set_var("HOME", v),
500 None => std::env::remove_var("HOME"),
501 }
502 match prev_userprofile {
503 Some(v) => std::env::set_var("USERPROFILE", v),
504 None => std::env::remove_var("USERPROFILE"),
505 }
506 }
507 }
508
509 #[test]
510 fn log_file_name_includes_pid() {
511 assert_eq!(
512 log_file_name("2026-05-18", 12345),
513 "tui-2026-05-18-12345.log"
514 );
515 }
516
517 #[test]
518 fn log_retention_days_uses_positive_env_override() {
519 let _lock = crate::test_support::lock_test_env();
520 let previous = std::env::var_os(LOG_RETENTION_ENV);
521
522 // SAFETY: serialised by lock_test_env.
523 unsafe {
524 std::env::set_var(LOG_RETENTION_ENV, "14");
525 }
526 assert_eq!(log_retention_days(), 14);
527
528 // SAFETY: serialised by lock_test_env.
529 unsafe {
530 std::env::set_var(LOG_RETENTION_ENV, "0");
531 }
532 assert_eq!(log_retention_days(), DEFAULT_LOG_RETENTION_DAYS);
533
534 // SAFETY: cleanup under the same lock.
535 unsafe {
536 match previous {
537 Some(value) => std::env::set_var(LOG_RETENTION_ENV, value),
538 None => std::env::remove_var(LOG_RETENTION_ENV),
539 }
540 }
541 }
542
543 #[test]
544 fn prune_old_logs_drops_only_stale_tui_logs() {
545 let tmp = tempfile::TempDir::new().unwrap();
546 let fresh = tmp.path().join("tui-2026-05-18-1.log");
547 let stale = tmp.path().join("tui-2026-05-01-2.log");
548 let legacy_stale = tmp.path().join("tui-2026-05-01.log");
549 let unrelated = tmp.path().join("agent-2026-05-01.log");
550
551 fs::write(&fresh, "fresh").unwrap();
552 fs::write(&stale, "stale").unwrap();
553 fs::write(&legacy_stale, "legacy").unwrap();
554 fs::write(&unrelated, "other").unwrap();
555
556 let now = SystemTime::now();
557 let old = now - Duration::from_secs(10 * SECONDS_PER_DAY);
558 set_modified(&stale, old);
559 set_modified(&legacy_stale, old);
560 set_modified(&unrelated, old);
561
562 let removed = prune_old_logs(tmp.path(), 7).unwrap();
563
564 assert_eq!(removed, 2);
565 assert!(fresh.exists());
566 assert!(!stale.exists());
567 assert!(!legacy_stale.exists());
568 assert!(unrelated.exists());
569 }
570
571 #[test]
572 fn log_directory_honors_codewhale_home_as_hard_override() {
573 let _lock = crate::test_support::lock_test_env();
574 let tmp = tempfile::TempDir::new().unwrap();
575 // SAFETY: serialised by lock_test_env.
576 unsafe {
577 std::env::set_var("CODEWHALE_HOME", tmp.path());
578 }
579 // $CODEWHALE_HOME IS the home dir (no ".codewhale" appended), and the
580 // legacy ~/.deepseek fallback is bypassed entirely.
581 let resolved = log_directory().expect("log_directory should resolve");
582 assert_eq!(resolved, tmp.path().join("logs"));
583 // SAFETY: cleanup under the same lock.
584 unsafe {
585 std::env::remove_var("CODEWHALE_HOME");
586 }
587 }
588 }
589
589 lines RUST