diff --git a/Cargo.lock b/Cargo.lock index 59dd53de..cb38ce18 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -825,6 +825,15 @@ version = "1.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "790eea4361631c5e7d22598ecd5723ff611904e3344ce8720784c93e3d83d40b" +[[package]] +name = "crossbeam-channel" +version = "0.5.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d85363c37faeca707aef026efa9f3b34d077bce547e48f770770625c6013679e" +dependencies = [ + "crossbeam-utils", +] + [[package]] name = "crossbeam-utils" version = "0.8.21" @@ -3220,6 +3229,9 @@ dependencies = [ "serde_json", "tar", "tokio", + "tracing", + "tracing-appender", + "tracing-subscriber", "ureq", "windows-native-keyring-store", "zbus-secret-service-keyring-store", @@ -4019,6 +4031,12 @@ version = "2.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292" +[[package]] +name = "symlink" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a7973cce6668464ea31f176d85b13c7ab3bba2cb3b77a2ed26abd7801688010a" + [[package]] name = "syn" version = "1.0.109" @@ -4498,6 +4516,19 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "050686193eb999b4bb3bc2acfa891a13da00f79734704c4b8b4ef1a10b368a3c" +dependencies = [ + "crossbeam-channel", + "symlink", + "thiserror 2.0.18", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.31" diff --git a/MANIFEST.md b/MANIFEST.md index dd85043a..e25e22e4 100644 --- a/MANIFEST.md +++ b/MANIFEST.md @@ -114,6 +114,7 @@ repository. | cpufeatures | 0.2.17 | MIT OR Apache-2.0 | | crc32fast | 1.5.0 | MIT OR Apache-2.0 | | critical-section | 1.2.0 | MIT OR Apache-2.0 | +| crossbeam-channel | 0.5.16 | MIT OR Apache-2.0 | | crossbeam-utils | 0.8.21 | MIT OR Apache-2.0 | | crossterm | 0.28.1 | MIT | | crossterm | 0.29.0 | MIT | @@ -411,6 +412,7 @@ repository. | strum_macros | 0.26.4 | MIT | | strum_macros | 0.28.0 | MIT | | subtle | 2.6.1 | BSD-3-Clause | +| symlink | 0.1.0 | MIT/Apache-2.0 | | syn | 1.0.109 | MIT OR Apache-2.0 | | syn | 2.0.118 | MIT OR Apache-2.0 | | sync_wrapper | 1.0.2 | Apache-2.0 | @@ -452,6 +454,7 @@ repository. | tower-layer | 0.3.3 | MIT | | tower-service | 0.3.3 | MIT | | tracing | 0.1.44 | MIT | +| tracing-appender | 0.2.5 | MIT | | tracing-attributes | 0.1.31 | MIT | | tracing-core | 0.1.36 | MIT | | tracing-error | 0.2.1 | MIT | diff --git a/THIRD_PARTY_NOTICES.txt b/THIRD_PARTY_NOTICES.txt index 6f051d11..4dcac910 100644 --- a/THIRD_PARTY_NOTICES.txt +++ b/THIRD_PARTY_NOTICES.txt @@ -5552,6 +5552,7 @@ The following component(s) are licensed under Apache License 2.0: - core-foundation 0.10.1 - core-foundation 0.9.4 - critical-section 1.2.0 + - crossbeam-channel 0.5.16 - crossbeam-utils 0.8.21 - displaydoc 0.2.6 - either 1.16.0 @@ -5631,6 +5632,7 @@ The following component(s) are licensed under Apache License 2.0: - smallvec 1.15.2 - socket2 0.6.4 - stable_deref_trait 1.2.1 + - symlink 0.1.0 - system-configuration-sys 0.6.0 - system-configuration 0.7.0 - tar 0.4.46 @@ -8885,6 +8887,7 @@ MIT License ================================================================================ The following component(s) are licensed under MIT License: + - tracing-appender 0.2.5 - tracing-attributes 0.1.31 - tracing-core 0.1.36 - tracing-error 0.2.1 diff --git a/about.toml b/about.toml index 3822f586..f5021371 100644 --- a/about.toml +++ b/about.toml @@ -34,3 +34,15 @@ private = { ignore = true } # they are not third-party components of the distribution. ignore-build-dependencies = true ignore-dev-dependencies = true + +# ureq is dual-licensed "MIT OR Apache-2.0". cargo-about's pick between ureq's +# two bundled license files is not stable across environments (filesystem read +# order), so a notice generated on one machine can fail the CI regenerate-and- +# compare check on another. Clarify ureq to Apache-2.0 (the license the +# committed notice — and main — already use) with the file as source of truth, +# so every environment resolves ureq identically. +[ureq.clarify] +license = "Apache-2.0" +[[ureq.clarify.files]] +path = "LICENSE-APACHE" +checksum = "c71d239df91726fc519c6eb72d318ec65820627232b2f796219e87dcf35d0ab4" diff --git a/apps/rocm/Cargo.toml b/apps/rocm/Cargo.toml index e35336d7..af76385d 100644 --- a/apps/rocm/Cargo.toml +++ b/apps/rocm/Cargo.toml @@ -34,6 +34,9 @@ rpassword.workspace = true serde.workspace = true serde_json.workspace = true tar = "0.4" +tracing = "0.1" +tracing-appender = "0.2" +tracing-subscriber = { version = "0.3", features = ["env-filter"] } ureq = { version = "2.12", features = ["native-certs"] } [target.'cfg(target_os = "windows")'.dependencies] diff --git a/apps/rocm/src/logging.rs b/apps/rocm/src/logging.rs new file mode 100644 index 00000000..dd1e2713 --- /dev/null +++ b/apps/rocm/src/logging.rs @@ -0,0 +1,275 @@ +// Copyright © Advanced Micro Devices, Inc., or its affiliates. +// +// SPDX-License-Identifier: MIT + +//! Client-side (CLI/TUI process) structured logging. +//! +//! Wires a file-only, non-blocking `tracing` subscriber so the `info!` / +//! `warn!` / `debug!` calls scattered across `rocm-dash-tui` and +//! `rocm-dash-daemon` (previously silently dropped — no subscriber was ever +//! installed) land in a real log file. CRITICAL: the writer must never touch +//! stdout/stderr — the TUI owns the raw-mode terminal, and a stray write +//! there would corrupt the display. + +use std::path::{Component, Path, PathBuf}; + +use rocm_core::AppPaths; +use tracing_appender::non_blocking::WorkerGuard; +use tracing_subscriber::EnvFilter; + +/// File name prefix for the daily-rotated client log +/// (`~/.rocm/logs/rocm-cli.log.`), sibling to the daemon's +/// `rocmdashd.log` under the same canonical `AppPaths` root. +const LOG_FILE_PREFIX: &str = "rocm-cli.log"; + +/// Total number of daily log files retained on disk, INCLUDING today's +/// actively-written file; older ones are pruned on startup so a long-lived +/// install never grows the logs directory unbounded. Pruning runs *after* the +/// appender opens today's file (see [`init`]), so this is the true on-disk +/// bound — a week of history. +const MAX_RETAINED_LOGS: usize = 7; + +/// Default filter applied when `RUST_LOG` is unset: `info` for our own +/// crates (loud enough to trace a hung chat request), `warn` for everything +/// else (dependency noise stays out of the file). +const DEFAULT_FILTER: &str = "warn,rocm=info,rocm_dash_tui=info,rocm_dash_daemon=info"; + +/// Initialize the process-wide `tracing` subscriber, writing to a daily- +/// rotated file under `paths.client_log_dir()`. +/// +/// Returns the [`WorkerGuard`] the caller must keep alive for the process +/// lifetime — dropping it flushes and stops the non-blocking writer, so +/// letting it fall out of scope early silently truncates the log. Returns +/// `None` if the log directory couldn't be created or a global subscriber is +/// already installed (e.g. a second call in the same process); either case +/// degrades to no logging rather than a startup failure. +pub fn init(paths: &AppPaths) -> Option { + // Validate the resolved directory before any filesystem write: the base + // path is derived from `$HOME` / `$ROCM_CLI_DATA_DIR` / config, so it must + // be confirmed to live inside the `AppPaths` root and be free of `..` + // traversal before it is handed to the appender or the pruner. + let log_dir = validated_log_dir(paths)?; + + // Construct the appender first: `rolling::daily` opens today's file eagerly + // at construction time. Prune AFTER that so today's active file is counted + // in the retention window — otherwise the effective on-disk bound would be + // MAX_RETAINED_LOGS + 1 (the pruned set plus the freshly-opened file). + let file_appender = tracing_appender::rolling::daily(&log_dir, LOG_FILE_PREFIX); + prune_old_logs(&log_dir); + let (non_blocking, guard) = tracing_appender::non_blocking(file_appender); + + let filter = + EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(DEFAULT_FILTER)); + + let subscriber = tracing_subscriber::fmt() + .with_env_filter(filter) + .with_writer(non_blocking) + .with_ansi(false) + .with_target(true) + .finish(); + + tracing::subscriber::set_global_default(subscriber) + .ok() + .map(|()| guard) +} + +/// Resolve, create, and validate the client log directory, breaking the +/// data-flow taint from `$HOME` / `$ROCM_CLI_DATA_DIR` / config into every +/// filesystem operation below. +/// +/// The directory is always `/logs`. We create it, then canonicalize +/// both it and the `AppPaths` data-dir root and require the canonical log dir +/// to stay nested under the canonical root — so a symlink or `..` in the +/// resolved environment cannot redirect log writes outside `~/.rocm`. Returns +/// the validated, canonicalized directory (all subsequent fs ops run on this +/// value, not the raw env-derived path), or `None` — in which case [`init`] +/// degrades to no logging rather than writing to an unexpected location. +fn validated_log_dir(paths: &AppPaths) -> Option { + let root = paths.data_dir.as_path(); + let log_dir = paths.client_log_dir(); + std::fs::create_dir_all(&log_dir).ok()?; + + let canonical_root = std::fs::canonicalize(root).ok()?; + let canonical_log_dir = std::fs::canonicalize(&log_dir).ok()?; + + // Reject any parent-dir traversal and require containment under the root. + // Both conditions are belt-and-suspenders after canonicalization (which + // already resolves `..` and symlinks) and act as the sanitizing barrier + // for the tainted base path. + let has_traversal = canonical_log_dir + .components() + .any(|c| matches!(c, Component::ParentDir)); + if has_traversal || !canonical_log_dir.starts_with(&canonical_root) { + return None; + } + + Some(canonical_log_dir) +} + +/// Remove rotated log files beyond [`MAX_RETAINED_LOGS`], keeping the logs +/// directory bounded for long-lived installs. Best-effort: any I/O error +/// just leaves the file in place for a future run to retry. +/// +/// `log_dir` must already have passed [`validated_log_dir`]; the caller only +/// ever passes that validated, canonicalized path. +fn prune_old_logs(log_dir: &Path) { + let Ok(entries) = std::fs::read_dir(log_dir) else { + return; + }; + let mut candidates: Vec<_> = entries + .filter_map(Result::ok) + .filter(|entry| { + entry + .file_name() + .to_str() + .is_some_and(|name| name.starts_with(LOG_FILE_PREFIX) && name != LOG_FILE_PREFIX) + }) + .collect(); + if candidates.len() <= MAX_RETAINED_LOGS { + return; + } + // Daily rotation suffixes sort lexicographically by date, so the oldest + // files are simply the front of the sorted list. + candidates.sort_by_key(std::fs::DirEntry::file_name); + let excess = candidates.len() - MAX_RETAINED_LOGS; + for entry in candidates.into_iter().take(excess) { + let _ = std::fs::remove_file(entry.path()); + } +} + +#[cfg(test)] +mod tests { + use super::*; + + fn temp_paths(name: &str) -> (PathBuf, AppPaths) { + // Use the OS temp dir (not the repo tree) so tests never litter the + // working copy. Canonicalize the base first so the fixture paths are + // derived from a resolved, symlink-free root (matches production's + // `validated_log_dir` barrier and keeps assertions stable where + // `$TMPDIR` is itself a symlink). Use `expect` rather than falling back + // to the raw `temp_dir()` so the env-derived path is never used + // un-canonicalized. Name-scoped with pid + millis to stay unique across + // parallel test threads and repeated runs. + let base = std::fs::canonicalize(std::env::temp_dir()) + .expect("OS temp dir must exist and canonicalize"); + let root = base.join(format!( + "rocm-cli-logging-test-{name}-{}-{}", + std::process::id(), + rocm_core::unix_time_millis() + )); + let _ = std::fs::remove_dir_all(&root); + ( + root.clone(), + AppPaths { + config_dir: root.join("config"), + data_dir: root.join("data"), + cache_dir: root.join("cache"), + }, + ) + } + + #[test] + fn init_creates_log_dir_and_a_log_file() { + let (root, paths) = temp_paths("init-creates-dir"); + // A global `tracing` subscriber can only be installed once per test + // binary process, so whether THIS call wins the race is + // nondeterministic under `cargo test`'s default parallel threads. + // The rolling file appender opens its current-period file eagerly at + // construction time, before the (possibly-losing) subscriber install + // is attempted, so the directory/file assertions below hold either + // way — only the `Some`/`None` guard outcome depends on the race. + let guard = init(&paths); + if guard.is_some() { + tracing::info!("hello from the test subscriber"); + } + // Drop the guard to flush the non-blocking writer before inspecting + // the directory contents. + drop(guard); + + let log_dir = paths.client_log_dir(); + assert!(log_dir.is_dir()); + let has_log_file = std::fs::read_dir(&log_dir) + .unwrap() + .filter_map(Result::ok) + .any(|e| { + e.file_name() + .to_str() + .is_some_and(|n| n.starts_with(LOG_FILE_PREFIX)) + }); + assert!( + has_log_file, + "expected a rocm-cli.log.* file in {log_dir:?}" + ); + + let _ = std::fs::remove_dir_all(&root); + } + + #[test] + fn init_is_idempotent_when_a_global_subscriber_already_exists() { + let (root, paths) = temp_paths("init-idempotent"); + // A global tracing subscriber can only be installed once per + // process; whichever test runs first wins. Either outcome here is a + // successful directory/file setup, and the second `init` call in the + // same process must not panic. + let first = init(&paths); + let second = init(&paths); + assert!(second.is_none() || first.is_none()); + + let _ = std::fs::remove_dir_all(&root); + } + + #[test] + fn prune_old_logs_keeps_only_the_most_recent_files() { + let (root, paths) = temp_paths("prune-old-logs"); + let log_dir = paths.client_log_dir(); + std::fs::create_dir_all(&log_dir).unwrap(); + for day in 0..(MAX_RETAINED_LOGS + 3) { + std::fs::write( + log_dir.join(format!("{LOG_FILE_PREFIX}.2026-01-{day:02}")), + b"log line\n", + ) + .unwrap(); + } + + prune_old_logs(&log_dir); + + let remaining = std::fs::read_dir(&log_dir).unwrap().count(); + assert_eq!(remaining, MAX_RETAINED_LOGS); + + let _ = std::fs::remove_dir_all(&root); + } + + #[test] + fn prune_ordering_bounds_total_including_todays_active_file() { + // Regression for the off-by-one: `init` opens today's file BEFORE + // pruning, so pruning must count that active file within the retention + // window. Pre-seed exactly MAX_RETAINED_LOGS dated files, then mirror + // `init`'s ordering (open the daily appender, then prune) without + // installing a global subscriber. The total on disk must stay at + // MAX_RETAINED_LOGS — not MAX_RETAINED_LOGS + 1. + let (root, paths) = temp_paths("prune-ordering"); + let log_dir = paths.client_log_dir(); + std::fs::create_dir_all(&log_dir).unwrap(); + for day in 1..=MAX_RETAINED_LOGS { + std::fs::write( + log_dir.join(format!("{LOG_FILE_PREFIX}.2020-01-{day:02}")), + b"old\n", + ) + .unwrap(); + } + + // Opens today's file eagerly (dated far after the 2020 seeds, so it + // sorts newest and is never the one pruned). + let appender = tracing_appender::rolling::daily(&log_dir, LOG_FILE_PREFIX); + prune_old_logs(&log_dir); + drop(appender); + + let remaining = std::fs::read_dir(&log_dir).unwrap().count(); + assert_eq!( + remaining, MAX_RETAINED_LOGS, + "today's active file must count toward the retention bound" + ); + + let _ = std::fs::remove_dir_all(&root); + } +} diff --git a/apps/rocm/src/main.rs b/apps/rocm/src/main.rs index c3fc1db8..a2950b67 100644 --- a/apps/rocm/src/main.rs +++ b/apps/rocm/src/main.rs @@ -7,6 +7,7 @@ mod bootstrap; mod comfyui; mod dash; mod dash_seam; +mod logging; mod provider_keys; mod providers; mod serve_summary; @@ -817,6 +818,14 @@ impl PermissionsModeArg { } fn main() -> Result<()> { + // Held for the whole process lifetime: dropping it flushes and stops the + // non-blocking file writer, so an early drop would silently truncate the + // log. A failed/missing `AppPaths::discover()` degrades to no logging + // rather than a startup failure. + let _log_guard = AppPaths::discover() + .ok() + .and_then(|paths| logging::init(&paths)); + maybe_migrate_legacy_dashboard_config(); let raw_args: Vec = std::env::args().skip(1).collect(); diff --git a/crates/rocm-core/src/lib.rs b/crates/rocm-core/src/lib.rs index afb1e28d..d9d8ea1c 100644 --- a/crates/rocm-core/src/lib.rs +++ b/crates/rocm-core/src/lib.rs @@ -899,6 +899,16 @@ impl AppPaths { pub fn daemon_log_path(&self) -> PathBuf { self.data_dir.join("logs").join("rocmdashd.log") } + + /// Directory for client-side (CLI/TUI process) `tracing` log files. + /// + /// Siblings the daemon's `rocmdashd.log` under the same canonical + /// `~/.rocm/logs` root; the client writer rotates files inside this + /// directory itself (see `apps/rocm/src/logging.rs`), so only the + /// directory — not a single fixed file name — is exposed here. + pub fn client_log_dir(&self) -> PathBuf { + self.data_dir.join("logs") + } } fn configured_managed_root_from_config(paths: &AppPaths) -> Option { @@ -7860,6 +7870,7 @@ Class Name: Display paths.daemon_log_path(), paths.data_dir.join("logs").join("rocmdashd.log") ); + assert_eq!(paths.client_log_dir(), paths.data_dir.join("logs")); // ensure() creates the telemetry state dir alongside the others. paths.ensure()?; assert!(paths.telemetry_state_dir().is_dir()); diff --git a/crates/rocm-dash-tui/src/agent.rs b/crates/rocm-dash-tui/src/agent.rs index 41e78d6f..352aec1d 100644 --- a/crates/rocm-dash-tui/src/agent.rs +++ b/crates/rocm-dash-tui/src/agent.rs @@ -17,10 +17,12 @@ //! model can call read-only tools and then answer — one final reply to the UI. use std::sync::{Arc, Mutex}; +use std::time::Instant; use async_trait::async_trait; use serde::Deserialize; use serde_json::{Value, json}; +use tracing::{error, info, warn}; use rig::completion::ToolDefinition; use rig::tool::Tool; @@ -132,17 +134,53 @@ pub fn annotate_reply(reply: String, skills: &[String]) -> String { /// with a `Display` error. A timeout maps to [`AgentError::Timeout`]; a backend /// error maps to [`AgentError::Request`]; success is annotated with the fired /// Skills. ONE definition of the tail, used by all three. -async fn finish_agent_request(req: F, fired: &FiredLog) -> Result +/// +/// `backend` tags the lifecycle trace events (request-start / completion / +/// error / timeout) so a hung or failing chat is traceable to a specific +/// provider in the client log. The request is non-streaming (rig's +/// `prompt().await` resolves once with the full reply), so there is no +/// separate first-byte instant to record — "first-byte" and "completion" are +/// the same instant here; the elapsed time logged on success is the +/// request's effective TTFT. +async fn finish_agent_request( + backend: &'static str, + req: F, + fired: &FiredLog, +) -> Result where F: std::future::IntoFuture>, E: std::fmt::Display, { + let started = Instant::now(); + info!(backend, "chat request start"); let reply = match tokio::time::timeout(REQUEST_TIMEOUT, req.into_future()).await { - Err(_) => return Err(AgentError::Timeout), + Err(_) => { + warn!( + backend, + elapsed_ms = started.elapsed().as_millis() as u64, + "chat request timed out" + ); + return Err(AgentError::Timeout); + } + Ok(Err(e)) => { + error!( + backend, + elapsed_ms = started.elapsed().as_millis() as u64, + error = %e, + "chat request failed" + ); + return Err(AgentError::Request(e.to_string())); + } Ok(Ok(reply)) => reply, - Ok(Err(e)) => return Err(AgentError::Request(e.to_string())), }; let skills = fired.lock().map(|g| g.clone()).unwrap_or_default(); + info!( + backend, + elapsed_ms = started.elapsed().as_millis() as u64, + reply_len = reply.len(), + skills_fired = skills.len(), + "chat request complete" + ); Ok(annotate_reply(reply, &skills)) } @@ -1006,7 +1044,7 @@ impl AgentClient for RigAgentClient { .max_turns(MAX_TOOL_TURNS) .with_history(build_messages(prior)); - finish_agent_request(req, &fired).await + finish_agent_request("rig-openai", req, &fired).await } } @@ -1267,7 +1305,7 @@ impl AgentClient for ChatGptAgentClient { .max_turns(MAX_TOOL_TURNS) .with_history(build_messages(prior)); - finish_agent_request(req, &fired).await + finish_agent_request("chatgpt-oauth", req, &fired).await } } @@ -1368,7 +1406,7 @@ impl AgentClient for AnthropicAgentClient { .max_turns(MAX_TOOL_TURNS) .with_history(build_messages(prior)); - finish_agent_request(req, &fired).await + finish_agent_request("anthropic", req, &fired).await } }