diff --git a/Cargo.lock b/Cargo.lock index 69958628352..4dbb09b552e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2657,6 +2657,8 @@ dependencies = [ "tempfile", "tokio", "toml 0.9.12+spec-1.1.0", + "tracing", + "tracing-subscriber", "unicode-width 0.2.0", "uuid", ] diff --git a/crates/fractal-feed/src/lib.rs b/crates/fractal-feed/src/lib.rs index 529226c2739..a108edf9d11 100644 --- a/crates/fractal-feed/src/lib.rs +++ b/crates/fractal-feed/src/lib.rs @@ -182,6 +182,8 @@ pub enum Update { /// The open conversation's entries. `replace` means these are its newest page and every /// earlier entry is gone; otherwise they are new or revised entries, matched by ID. Conversation { + /// The wire subscription that delivered this frame, for content-free diagnostics. + subscription_id: String, target: String, /// The session the entries belong to: earlier pages are read from its timeline. session_id: String, @@ -802,7 +804,7 @@ async fn connected( CollectionEvent::Conversation { id, session_id, replace, items, has_more, header, .. } => { let Some(current) = conversing.iter_mut().find(|current| current.id == id) else { continue }; current.served(); - if updates.send(Update::Conversation { target: current.target.clone(), session_id, replace, has_more, items, header }).is_err() { + if updates.send(Update::Conversation { subscription_id: id, target: current.target.clone(), session_id, replace, has_more, items, header }).is_err() { return Ended::Closed; } } diff --git a/crates/fractal-tui/Cargo.toml b/crates/fractal-tui/Cargo.toml index 4c6244a51a7..995a22916e8 100644 --- a/crates/fractal-tui/Cargo.toml +++ b/crates/fractal-tui/Cargo.toml @@ -32,6 +32,8 @@ base64 = "0.22" flate2 = "1" unicode-width = "0.2.0" reqwest = { version = "0.12", default-features = false } +tracing = "0.1" +tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt", "registry", "std"] } # Thumbnails of attached images: kitty placeholders, sixel or iTerm2, else half blocks. ratatui-image = { version = "11", default-features = false, features = ["crossterm"] } image = { version = "0.25", default-features = false, features = ["png", "jpeg", "gif", "webp"] } diff --git a/crates/fractal-tui/src/lib.rs b/crates/fractal-tui/src/lib.rs index ebe398314c5..c863e63e609 100644 --- a/crates/fractal-tui/src/lib.rs +++ b/crates/fractal-tui/src/lib.rs @@ -977,6 +977,7 @@ pub fn run(mut options: Args) -> Result<()> { return Ok(()); } let open_timing = ui::open_timing::Trace::from_env(process_started); + let _freshness = ui::freshness::install()?; fractal_client::set_client_name(version::client_name()); ui::lastrun_log_panics(&version::short(version::now())); if let Some(path) = std::env::var_os("FRACTAL_TUI_TIMING_LOG") { diff --git a/crates/fractal-tui/src/ui/freshness.rs b/crates/fractal-tui/src/ui/freshness.rs new file mode 100644 index 00000000000..33c09a313a7 --- /dev/null +++ b/crates/fractal-tui/src/ui/freshness.rs @@ -0,0 +1,97 @@ +//! Opt-in metadata only: never pass entries, bodies, headers, or rendered text to tracing. + +pub(super) fn enabled() -> bool { + static ENABLED: std::sync::LazyLock = std::sync::LazyLock::new(|| { + std::env::var_os("FRACTAL_TUI_FRESHNESS").is_some_and(|v| v == "1") + }); + *ENABLED +} + +pub(crate) fn install() -> anyhow::Result> { + use tracing_subscriber::prelude::*; + if !enabled() { + return Ok(None); + } + let path = std::env::var_os("FRACTAL_TUI_FRESHNESS_LOG") + .ok_or_else(|| anyhow::anyhow!("FRACTAL_TUI_FRESHNESS_LOG must name a private log file"))?; + let mut options = std::fs::OpenOptions::new(); + options.create(true).append(true); + #[cfg(unix)] + { + use std::os::unix::fs::OpenOptionsExt; + options.mode(0o600); + } + let file = options.open(path)?; + let layer = tracing_subscriber::fmt::layer() + .with_ansi(false) + .with_writer(std::sync::Mutex::new(file)) + .with_filter(tracing_subscriber::filter::filter_fn(|metadata| { + metadata.target() == "fractal_tui::freshness" + && *metadata.level() == tracing::Level::DEBUG + })); + Ok(Some(tracing::subscriber::set_default( + tracing_subscriber::registry().with(layer), + ))) +} + +pub(super) fn newest(items: &[fractal_client::TimelineEntry]) -> Option<(&str, u64, &str)> { + items.iter().map(|entry| (entry.timestamp.as_str(), entry.sequence, entry.id.as_str())).max() +} + +impl super::Ui { + pub(super) fn freshness_panes(&self, phase: &str) { + if !enabled() { + return; + } + let main = self.main_pane_key(); + let focused = self.focused_pane().map(|pane| pane.key()); + let frame = self.frame.borrow(); + let states = self.conversation_state.panes.borrow(); + tracing::debug!(target: "fractal_tui::freshness", stage = phase, + main_pane_key = ?main, focused_pane = ?focused, pane_count = frame.panes.len()); + for pane in &frame.panes { + let state = states.get(&pane.key).copied().unwrap_or_default(); + let entries = pane.key.strip_prefix("chat:") + .and_then(|target| self.world.conversations.get(target)) + .and_then(|load| match load { + super::view::Load::Ready(entries) => Some(entries), + _ => None, + }); + tracing::debug!(target: "fractal_tui::freshness", stage = phase, + pane = pane.key, follow = state.follow, top = state.top, + total = pane.total, height = pane.rect.height, + adapted_last_id = entries.and_then(|entries| entries.last()).map(|entry| entry.id.as_str()), + adapted_count = entries.map(Vec::len), + main_pane_key = ?main, focused_pane = ?focused); + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn maximum_is_timestamp_sequence_id_not_arrival_order() { + let entry = |id: &str, timestamp: &str, sequence| fractal_client::TimelineEntry { + id: id.into(), + timestamp: timestamp.into(), + sequence, + revision: 1, + delivers: None, + role: fractal_client::TimelineRole::System, + is_final: true, + body: fractal_client::TimelineBody::Error(fractal_client::TimelineErrorBody { + code: "test".into(), message: "must not be logged".into(), retryable: false, + }), + }; + assert_eq!(newest(&[]), None); + let items = [ + entry("b", "2026-11-10T22:00:42.105Z", 2), + entry("a", "2026-11-10T22:00:42.105Z", 2), + entry("c", "2026-11-10T22:00:42.105Z", 1), + entry("d", "2026-11-10T22:00:40.129Z", 100), + ]; + assert_eq!(newest(&items), Some(("2026-11-10T22:00:42.105Z", 2, "b"))); + } +} diff --git a/crates/fractal-tui/src/ui/live.rs b/crates/fractal-tui/src/ui/live.rs index fc88a98fa3c..a00a8f3a154 100644 --- a/crates/fractal-tui/src/ui/live.rs +++ b/crates/fractal-tui/src/ui/live.rs @@ -551,6 +551,10 @@ pub fn run(context: Context) -> Result<()> { // Messages sent from here, shown at once until st reports them back. let mut pending: Vec = Vec::new(); let mut ui = Ui::new(adapt::world(&model, &person, &extras)); + if super::freshness::enabled() { + tracing::debug!(target: "fractal_tui::freshness", stage = "startup", + version = %crate::version::short(crate::version::now()), endpoint = ?client); + } ui.load_prefs(); // A demo's agents are scripted stand-ins whose terminals stay empty: they open on their // conversation, without changing this device's choice. @@ -724,6 +728,10 @@ pub fn run(context: Context) -> Result<()> { agents_live = false; glasses_ready = true; client = member; + if super::freshness::enabled() { + tracing::debug!(target: "fractal_tui::freshness", stage = "connected", + version = %crate::version::short(crate::version::now()), endpoint = ?client); + } resources_generation += 1; resources_stale = true; extras.inventory_supported = None; @@ -867,6 +875,7 @@ pub fn run(context: Context) -> Result<()> { changed = true; } feed::Update::Conversation { + subscription_id, target, session_id, replace, @@ -874,6 +883,12 @@ pub fn run(context: Context) -> Result<()> { items, header, } => { + if super::freshness::enabled() { + tracing::debug!(target: "fractal_tui::freshness", stage = "frame", + subscription_id, target_id = target, frame_session = session_id, + newest = ?super::freshness::newest(&items), count = items.len(), replace); + ui.freshness_panes("update_before"); + } if let Some(trace) = &mut open_timing { trace.received(&target, items.len()); } @@ -890,7 +905,7 @@ pub fn run(context: Context) -> Result<()> { .insert(target.clone(), header.clone()); } filled.entry(target.clone()).or_default().apply( - timelines.entry(target).or_default(), + timelines.entry(target.clone()).or_default(), fractal_conversation_ui::Frame { replace, has_more, @@ -899,6 +914,15 @@ pub fn run(context: Context) -> Result<()> { header, }, ); + if super::freshness::enabled() { + let held = &timelines[&target]; + tracing::debug!(target: "fractal_tui::freshness", stage = "held", + subscription_id, target_id = target, + held_session = ?held.session_id, + newest = ?super::freshness::newest(&held.items), + newest_id = held.items.last().map(|entry| entry.id.as_str()), + count = held.items.len()); + } // A message sent from here is done once st shows it in the conversation. pending.retain(|pending| { let Some(id) = pending.message_id.as_ref() else { @@ -2033,6 +2057,7 @@ pub fn run(context: Context) -> Result<()> { || execute!(io::stdout(), EndSynchronizedUpdate), |target| ui.conversation_entry_visible(target), )?; + ui.freshness_panes("presented"); ui.quality.live(extras.live); let top = u8::from(extras.live) | (u8::from(extras.offline.is_some()) << 1) @@ -2296,6 +2321,12 @@ fn conversations( if let Some(note) = history_note(timeline) { entries.insert(0, note); } + if super::freshness::enabled() { + tracing::debug!(target: "fractal_tui::freshness", stage = "adapted", + target_id = target, held_session = ?timeline.session_id, + last_id = entries.last().map(|entry| entry.id.as_str()), + count = entries.len()); + } Load::Ready(entries) } (None, Some(error)) => { diff --git a/crates/fractal-tui/src/ui/mod.rs b/crates/fractal-tui/src/ui/mod.rs index 7b468cde02e..5090cf77de3 100644 --- a/crates/fractal-tui/src/ui/mod.rs +++ b/crates/fractal-tui/src/ui/mod.rs @@ -33,6 +33,7 @@ mod terminal_tab; #[cfg(test)] #[path = "../../tests/support/attach_default.rs"] mod attach_default; +pub(crate) mod freshness; pub use glass::set_glasses_version; pub use lastrun::log_panics as lastrun_log_panics; pub use lastrun::note_exit as lastrun_note_exit; @@ -3042,6 +3043,17 @@ impl Ui { } *state }; + if freshness::enabled() && key.starts_with("chat:") { + tracing::debug!( + target: "fractal_tui::freshness", + stage = "document", pane = key, + document_last_id = doc.entries.last().map(|(id, _)| id.as_str()), + line_count = total, follow = state.follow, top = state.top, + total, height, + main_pane_key = ?self.main_pane_key(), + focused_pane = ?self.focused_pane().map(|pane| pane.key()), + ); + } let top = state.top; if matches!( Pane::parse(key), @@ -4812,8 +4824,10 @@ impl Ui { KeyCode::PageDown => self.scroll_main(self.page() as isize), KeyCode::Home => self.scroll_main(-100_000), KeyCode::End => { + self.freshness_panes("end_before"); self.follow_latest(); self.scroll_main(100_000); + self.freshness_panes("end_after"); } KeyCode::Char('x') if self.tab() == 2 => self.system = !self.system, KeyCode::Enter if self.tab() == 1 && key.modifiers.contains(KeyModifiers::CONTROL) => self.toggle_focused_tool(), diff --git a/docs/when-something-is-wrong.md b/docs/when-something-is-wrong.md index 678ae806431..71f8e8af20a 100644 --- a/docs/when-something-is-wrong.md +++ b/docs/when-something-is-wrong.md @@ -87,6 +87,33 @@ fractal usage --hours 24 --by mission These are observed token totals. Cost is an API-equivalent estimate, and unpriced models are shown as unpriced. Account limits and stop policies can explain why an agent stopped; the agent's reason is more useful than repeatedly restarting it. See [model accounts](st3/accounts.md). +## A conversation does not follow new entries + +The footer's updated time means a frame arrived, not that its newest entry was +displayed. To locate a stale conversation inside the TUI, start a new process: + +```sh +umask 077 +FRACTAL_TUI_FRESHNESS=1 FRACTAL_TUI_FRESHNESS_LOG="$HOME/tui-freshness.log" fractal tui +``` + +This opt-in DEBUG trace writes only the `fractal_tui::freshness` target to the +append-only log, not the terminal. No `RUST_LOG` setting is required. Unset the +variables to disable it. Protect the file: identifiers, endpoints and timestamps +are metadata, not anonymous data. No message bodies, headers, tool arguments, +rendered text, or authentication credentials are recorded. + +Compare `frame` (subscription, target, session, replacement flag, count and maximum +timestamp/sequence/id), `held` (merged session, newest entry and count), `adapted` +(last displayed entry and count), and `document` (last rendered entry and line +count). Filtering and folded tool runs can intentionally change the last ID. +`startup` and `connected` identify the binary build and endpoint; `update_before`, +`presented`, `end_before` and `end_after` record pane keys, focused/main pane, +follow state, top, total and height. `document` runs during drawing, so use +`presented` for the complete frame's pane binding. End's `end_after` is before +redrawing; the next `document`/`presented` pair shows the resulting viewport. +The first stage that stops advancing identifies where to investigate next. + ## Recover the cause Finish a first-run prompt by attaching, then detach with **Ctrl+\\**: diff --git a/examples/client-tui/src/lib.rs b/examples/client-tui/src/lib.rs index 164ca093401..c7d6173ad43 100644 --- a/examples/client-tui/src/lib.rs +++ b/examples/client-tui/src/lib.rs @@ -151,6 +151,7 @@ impl App { has_more, items, header, + .. } if self.selected.as_ref() == Some(&target) => { self.timeline.apply(fractal_conversation_ui::Frame { replace, diff --git a/release-notes/tui-freshness-probe.json b/release-notes/tui-freshness-probe.json new file mode 100644 index 00000000000..3c8e152260a --- /dev/null +++ b/release-notes/tui-freshness-probe.json @@ -0,0 +1,11 @@ +{ + "version": 1, + "summary": "An opt-in, content-free TUI DEBUG log traces conversation freshness from subscription frames through held entries, adaptation, documents and pane follow state", + "replay": {"status": "none", "detail": "No graph replay."}, + "schema": {"status": "none", "detail": "No database or claim schema change."}, + "rules": {"status": "none", "detail": "No checkpoint rule change."}, + "compatibility": {"status": "changed", "detail": "The Rust feed Conversation update now includes its subscription ID; wire and stored formats are unchanged. Conversation display behavior is unchanged."}, + "downtime": {"status": "none", "detail": "None."}, + "manual": {"status": "none", "detail": "Optional diagnostics use FRACTAL_TUI_FRESHNESS=1 and FRACTAL_TUI_FRESHNESS_LOG as documented in the troubleshooting guide."}, + "recovery": {"status": "none", "detail": "Unset the diagnostic environment variables to stop logging. No stored conversation data changes."} +}