From e16f2f046e985e39a5f49d4c5558143e2c63729d Mon Sep 17 00:00:00 2001 From: Justin Scroggins Date: Mon, 2 Nov 2026 19:53:38 -0500 Subject: [PATCH 1/2] Add a Logs window that tails tinyclient, chatd and mediad live, and a Verbose logging switch that takes effect in all three without a restart. Co-Authored-By: Claude Opus 5.5 --- crates/chatd/src/media.rs | 15 + crates/chatd/src/server.rs | 3 + crates/mediad/src/lib.rs | 8 + crates/mediad/src/probe.rs | 1 + crates/mediad/src/serve.rs | 4 + crates/protocol/src/call.rs | 4 + crates/protocol/src/log_policy.rs | 50 +- crates/tinyclient/src/gui/app/menubar.rs | 4 + crates/tinyclient/src/gui/logs.rs | 497 ++++++++++++++++++++ crates/tinyclient/src/gui/mod.rs | 3 +- crates/tinyclient/src/gui/settings/pages.rs | 36 +- crates/tinyclient/src/gui/settings/rows.rs | 4 +- crates/tinyclient/src/lib.rs | 3 + crates/tinyclient/src/log_tail.rs | 411 ++++++++++++++++ crates/tinyclient/src/main.rs | 4 + docs/logging.md | 4 + docs/product/09-settings.md | 3 +- 17 files changed, 1025 insertions(+), 29 deletions(-) create mode 100644 crates/tinyclient/src/gui/logs.rs create mode 100644 crates/tinyclient/src/log_tail.rs diff --git a/crates/chatd/src/media.rs b/crates/chatd/src/media.rs index 35be3878..ea325c35 100644 --- a/crates/chatd/src/media.rs +++ b/crates/chatd/src/media.rs @@ -800,6 +800,21 @@ impl Calls { } } + /// Verbose logging changed: the call's mediad, or the test's, logs at the new ceiling from + /// its next line. A mediad started later reads it from its environment (`share_session`). + pub fn relevel(&self) { + let Some(guard) = protocol::log_policy::current() else { + return; + }; + let level = MediaRequest::LogLevel { level: guard.policy().level_word().to_owned() }; + if let Some(active) = crate::hub::lock(&self.slot).running() { + let _ = active.request(&level); + } + if let Some(tester) = crate::hub::lock(&self.tester).as_mut() { + let _ = tester.send(&level); + } + } + /// V1 or V2 changed: the call's mediad, or the test's, opens the new choice at once, and /// the next call starts with it too. pub fn redevice(&self, hub: &Hub) { diff --git a/crates/chatd/src/server.rs b/crates/chatd/src/server.rs index 28ab6e53..3c61a865 100644 --- a/crates/chatd/src/server.rs +++ b/crates/chatd/src/server.rs @@ -420,6 +420,8 @@ impl Chat { | settings::NOISE_SUPPRESSION | settings::AUTO_GAIN => self.hub.calls.retune(&self.hub), settings::INPUT | settings::OUTPUT => self.hub.calls.redevice(&self.hub), + // `set_setting` has already moved chatd's own ceiling. + settings::LOG_LEVEL => self.hub.calls.relevel(), _ => {} } Response::Ok @@ -434,6 +436,7 @@ impl Chat { self.hub.prune_soon(); self.hub.calls.retune(&self.hub); self.hub.calls.redevice(&self.hub); + self.hub.calls.relevel(); Response::Ok } diff --git a/crates/mediad/src/lib.rs b/crates/mediad/src/lib.rs index d75cca99..ad89af4a 100644 --- a/crates/mediad/src/lib.rs +++ b/crates/mediad/src/lib.rs @@ -58,3 +58,11 @@ pub const CHANNELS: usize = 2; pub const FRAME: usize = 960; /// Interleaved samples in one frame. pub const FRAME_SAMPLES: usize = FRAME * CHANNELS; + +/// chatd's Verbose logging changed while this mediad runs (`MediaRequest::LogLevel`): the file +/// takes the new ceiling from the next line. An unknown word leaves it as it was. +pub fn relevel(level: &str) { + if let Some(guard) = protocol::log_policy::current() { + guard.apply(guard.policy().overlay_stored(Some(level), None, None)); + } +} diff --git a/crates/mediad/src/probe.rs b/crates/mediad/src/probe.rs index 74e1f1bc..576db839 100644 --- a/crates/mediad/src/probe.rs +++ b/crates/mediad/src/probe.rs @@ -90,6 +90,7 @@ pub fn run() { out::send(&MediaResponse::LogsSaved { path }); continue; } + MediaRequest::LogLevel { level } => crate::relevel(&level), _ => { out::send(&MediaResponse::Refused { detail: "There is no call.".to_owned() }); continue; diff --git a/crates/mediad/src/serve.rs b/crates/mediad/src/serve.rs index 85d81d6a..6808277c 100644 --- a/crates/mediad/src/serve.rs +++ b/crates/mediad/src/serve.rs @@ -314,6 +314,10 @@ impl Call { .unwrap_or_default(); return MediaResponse::LogsSaved { path }; } + MediaRequest::LogLevel { level } => { + crate::relevel(&level); + return MediaResponse::Done; + } } MediaResponse::Streams { video: self.video.streams() } } diff --git a/crates/protocol/src/call.rs b/crates/protocol/src/call.rs index 7e61efec..0b76219b 100644 --- a/crates/protocol/src/call.rs +++ b/crates/protocol/src/call.rs @@ -429,6 +429,10 @@ pub enum MediaRequest { Loopback { on: bool }, /// Write mediad's debug ring. Answered `LogsSaved`. SaveLogs, + /// The log ceiling changed in chatd's settings (Verbose logging): `error`, `warn`, `info`, + /// `debug` or `trace`, as `settings::LOG_LEVEL` holds it. Answered `Done`; an unknown word + /// changes nothing. + LogLevel { level: String }, } /// The loudest one participant may be set, in percent. diff --git a/crates/protocol/src/log_policy.rs b/crates/protocol/src/log_policy.rs index 0f9b4670..f1f29253 100644 --- a/crates/protocol/src/log_policy.rs +++ b/crates/protocol/src/log_policy.rs @@ -149,6 +149,16 @@ impl LogPolicy { self.operator } + /// The operator ceiling as a stored setting would name it: `debug`, `info`, ... + pub fn level_word(&self) -> &'static str { + level_name(self.operator) + } + + /// Whether the files carry debug lines: Verbose logging, or `TINYCLIENT_LOG_LEVEL=debug`. + pub fn verbose(&self) -> bool { + self.operator >= Level::DEBUG + } + pub fn ring_enabled(&self) -> bool { self.ring } @@ -297,9 +307,14 @@ pub fn adopt_session(id: &str) { } /// Puts this process's session on a child. chatd generates the id in memory when nothing -/// set the variable, so inheritance alone would give mediad and login a different one. +/// set the variable, so inheritance alone would give mediad and login a different one. The +/// ceiling goes too: a stored Verbose logging lives in chatd's settings, which a helper never +/// reads, so a mediad started after it was turned on starts at debug. pub fn share_session(command: &mut std::process::Command) { command.env("TINYCLIENT_SESSION", session_id()); + if let Some(guard) = current() { + command.env("TINYCLIENT_LOG_LEVEL", guard.policy().level_word()); + } } fn load_session() -> String { @@ -623,8 +638,19 @@ pub struct LogGuard { impl LogGuard { /// Replaces the ceilings and the export flag. The open file stays open. + /// A new operator ceiling is written to the file, so the Logs window shows Verbose logging + /// taking hold in each process. pub fn apply(&self, policy: LogPolicy) { - *self.policy.lock().unwrap_or_else(|err| err.into_inner()) = policy; + let before = std::mem::replace(&mut *self.policy.lock().unwrap_or_else(|err| err.into_inner()), policy); + if before.operator != policy.operator { + // Under the new ceiling, so at warn when that is quieter than info. + let line = format!("{}: log level is now {}", self.process, policy.level_word()); + if policy.operator >= Level::INFO { + tracing::info!("{line}"); + } else { + tracing::warn!("{line}"); + } + } } pub fn policy(&self) -> LogPolicy { @@ -887,6 +913,26 @@ mod tests { assert!(!off.export_enabled()); } + #[test] + fn verbose_is_debug_or_more_and_the_word_round_trips() { + for (word, verbose) in [("error", false), ("warn", false), ("info", false), ("debug", true), ("trace", true)] { + let policy = LogPolicy::policy_from_values(Some(word), None, None); + assert_eq!(policy.verbose(), verbose, "{word}"); + assert_eq!(policy.level_word(), word); + } + let raised = LogPolicy::default().overlay_stored(Some("debug"), None, None); + assert!(raised.verbose() && raised.ring_enabled()); + } + + #[test] + fn a_log_level_request_reads_and_an_older_frame_still_does() { + let request = crate::MediaRequest::LogLevel { level: "debug".to_owned() }; + let text = serde_json::to_string(&request).unwrap_or_default(); + assert_eq!(text, r#"{"media":"log_level","level":"debug"}"#); + assert_eq!(serde_json::from_str::(&text).ok(), Some(request)); + assert_eq!(serde_json::from_str::(r#"{"media":"save_logs"}"#).ok(), Some(crate::MediaRequest::SaveLogs)); + } + #[test] fn log_settings_default_and_reject_garbage() { assert_eq!(LogPolicy::apply_settings("", "", "").operator_level(), Level::INFO); diff --git a/crates/tinyclient/src/gui/app/menubar.rs b/crates/tinyclient/src/gui/app/menubar.rs index f3ae52aa..a59760d9 100644 --- a/crates/tinyclient/src/gui/app/menubar.rs +++ b/crates/tinyclient/src/gui/app/menubar.rs @@ -128,6 +128,7 @@ pub fn menus(places: &[(String, usize)], open_network: Option, update_i Menu::new("Help").items([ MenuItem::action("Keyboard Shortcuts", KeyboardShortcuts), MenuItem::action("Copy Diagnostics", CopyDiagnostics), + MenuItem::action("Logs", ShowLogs), ]), ] } @@ -152,7 +153,9 @@ pub fn bind_keys(cx: &mut App) { KeyBinding::new("alt-secondary-o", OpenInNetwork, None), KeyBinding::new("secondary-m", Minimize, None), KeyBinding::new("secondary-/", KeyboardShortcuts, None), + KeyBinding::new("secondary-shift-l", ShowLogs, None), ]); + super::super::logs::bind_keys(cx); // Hiding is macOS's. Linux ignores it, and GPUI on Windows panics at Hide Others. if cfg!(target_os = "macos") { cx.bind_keys([KeyBinding::new("secondary-h", Hide, None), KeyBinding::new("alt-secondary-h", HideOthers, None)]); @@ -222,6 +225,7 @@ pub fn app_actions(cx: &mut App) { .detach(); }); cx.on_action(|_: &KeyboardShortcuts, cx| settings::open(settings::Section::Shortcuts, cx)); + cx.on_action(|_: &ShowLogs, cx| super::super::logs::open(cx)); } impl Shell { diff --git a/crates/tinyclient/src/gui/logs.rs b/crates/tinyclient/src/gui/logs.rs new file mode 100644 index 00000000..c7db55ab --- /dev/null +++ b/crates/tinyclient/src/gui/logs.rs @@ -0,0 +1,497 @@ +//! The Logs window (Help › Logs, ⇧⌘L, or View logs in Settings › About): the live tail of +//! tinyclient's, chatd's and mediad's files (`log_tail`), with a filter, so a problem can be +//! watched as it happens rather than saved and opened afterwards. +//! +//! The files are read off the main thread every half second while the window is open, and not +//! at all once it closes. A file watcher would wake only on a write, but it is a new dependency +//! for one window that is closed nearly all the time. +//! +//! Verbose logging is chatd's stored `log_level` setting, so all three processes change at once +//! without a restart: chatd moves its own ceiling when the setting is stored and tells a running +//! mediad (`MediaRequest::LogLevel`); the window takes it up with the settings it reads back; and +//! a mediad started later is given it in its environment (`share_session`). + +use super::app::prefs; +use super::components::{button, search_field, segment, segmented, ButtonKind}; +use super::input::{InputEvent, InputKey, TextInput}; +use super::settings::controls::switch; +use super::theme::{self, Type}; +use crate::log_tail::{self, Filter, Follow, Level, Line, Source, Tail}; +use gpui::{ + div, point, prelude::*, px, size, uniform_list, AnyElement, App, Bounds, ClipboardItem, Context, Entity, FocusHandle, Focusable, + Global, KeyBinding, ListHorizontalSizingBehavior, SharedString, Subscription, Task, TitlebarOptions, UniformListScrollHandle, Window, + WindowBounds, WindowHandle, WindowOptions, +}; +use protocol::log_policy::LogPolicy; +use protocol::settings::{GLOBAL, LOG_LEVEL}; +use protocol::{Request, Response}; +use std::ops::Range; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +const SIZE: (f32, f32) = (1000., 640.); +const MIN_SIZE: (f32, f32) = (720., 360.); +/// How often the files are read while the window is open. +const POLL: Duration = Duration::from_millis(500); +/// One line of the list. +const ROW: f32 = 18.; +/// The column naming a line's process, when every process is shown. +const SOURCE_COLUMN: f32 = 84.; +/// How long a note ("Copied 40 lines") stays. +const NOTE: Duration = Duration::from_secs(4); + +gpui::actions!(logs, [Dismiss]); + +/// The window, once it is open. +#[derive(Default)] +struct Host { + window: Option>, +} + +impl Global for Host {} + +pub fn bind_keys(cx: &mut App) { + cx.bind_keys([KeyBinding::new("escape", Dismiss, Some("Logs"))]); +} + +/// Opens the Logs window, or brings the open one forward. A phone has no log files to show. +/// Safe to call from inside another view's update. +pub fn open(cx: &mut App) { + if super::phone::active() { + return; + } + cx.defer(open_now); +} + +fn open_now(cx: &mut App) { + if let Some(window) = cx.default_global::().window { + if window.update(cx, |_, window, _| window.activate()).is_ok() { + return; + } + } + let bounds = Bounds::centered(None, size(px(SIZE.0), px(SIZE.1)), cx); + let options = WindowOptions { + window_bounds: Some(WindowBounds::Windowed(bounds)), + window_min_size: Some(size(px(MIN_SIZE.0), px(MIN_SIZE.1))), + titlebar: Some(TitlebarOptions { + title: Some("Logs".into()), + appears_transparent: true, + traffic_light_position: Some(point(px(12.), px(20.))), + }), + window_decorations: Some(gpui::WindowDecorations::Server), + app_id: Some(super::APP_ID.into()), + ..Default::default() + }; + match cx.open_window(options, |window, cx| cx.new(|cx| LogsWindow::new(window, cx))) { + Ok(window) => cx.default_global::().window = Some(window), + Err(err) => tracing::warn!("tinyclient: the Logs window could not open: {err}"), + } +} + +/// Writes each process's debug ring to `logs/bundles` (Save debug log), and returns the files +/// written. Blocks on chatd: call it off the main thread. +pub fn save_bundles() -> Vec { + let mut paths = Vec::new(); + if let Some(guard) = protocol::log_policy::current() { + if let Ok(Some(path)) = guard.export_bundle() { + paths.push(path.display().to_string()); + } + } + if let Ok(Response::LogsSaved { paths: more }) = crate::client::ask(&Request::SaveLogs) { + paths.extend(more); + } + paths +} + +/// What Save debug log says once it is done. +pub fn saved_note(paths: &[String]) -> String { + if paths.is_empty() { + "Debug logs are turned off.".to_owned() + } else { + protocol::log_policy::logs_dir().join("bundles").display().to_string() + } +} + +/// Whether this machine's files carry debug lines: the stored Verbose logging, or +/// `TINYCLIENT_LOG_LEVEL` when nothing is stored. +pub fn verbose() -> bool { + LogPolicy::for_settings(&prefs::values()).verbose() +} + +/// The `log_level` to store for Verbose logging `on`. Off clears the row, unless the environment +/// alone would keep the files at debug, when it stores `info` so the switch does what it says. +pub fn verbose_value(on: bool) -> Option { + if on { + Some("debug".to_owned()) + } else { + LogPolicy::from_env().verbose().then(|| "info".to_owned()) + } +} + +/// The line under Verbose logging, wherever it is drawn. +pub const VERBOSE_NOTE: &str = "tinyclient, chatd and calls write debug lines at once, and after a restart."; + +/// Reads what each file gained. A file that cannot be read this time is tried again next time. +fn read_all(follows: &Mutex>) -> Vec<(Source, Vec)> { + let mut follows = follows.lock().unwrap_or_else(|err| err.into_inner()); + follows.iter_mut().filter_map(|(source, follow)| follow.read().ok().filter(|lines| !lines.is_empty()).map(|lines| (*source, lines))).collect() +} + +pub struct LogsWindow { + tail: Tail, + filter: Filter, + search: Entity, + /// What the list draws: the filter over the tail, as of the last refresh. Held still while + /// paused, so the line under the pointer does not move. + visible: Vec>, + /// The longest visible line, which sets how far the list scrolls sideways. + longest: usize, + /// The newest line's number when auto-scroll was paused; `None` while it follows the end. + paused_at: Option, + scroll: UniformListScrollHandle, + focus: FocusHandle, + note: Option<(Instant, String)>, + _poll: Task<()>, + _subscriptions: Vec, +} + +impl LogsWindow { + fn new(window: &mut Window, cx: &mut Context) -> LogsWindow { + let search = cx.new(|cx| TextInput::new("Filter lines", cx)); + let subscriptions = vec![ + cx.subscribe_in(&search, window, |this, input, event: &InputEvent, _, cx| { + if let InputEvent::Changed = event { + this.filter.text = input.read(cx).text().to_owned(); + this.refresh(cx); + } + }), + cx.subscribe_in(&search, window, |this, _, event: &InputKey, window, cx| { + if *event == InputKey::Escape { + this.dismiss(window, cx); + } + }), + ]; + // Where each file has been read to lives with the loop, which is dropped with the window. + let reading = Arc::new(Mutex::new(Source::ALL.iter().map(|source| (*source, Follow::new(source.path()))).collect::>())); + let poll = cx.spawn(async move |this, cx| loop { + let follows = reading.clone(); + let read = cx.background_executor().spawn(async move { read_all(&follows) }).await; + if this.update(cx, |this, cx| this.take(read, cx)).is_err() { + break; + } + cx.background_executor().timer(POLL).await; + }); + let focus = cx.focus_handle(); + window.focus(&search.focus_handle(cx), cx); + LogsWindow { + tail: Tail::default(), + filter: Filter::default(), + search, + visible: Vec::new(), + longest: 0, + paused_at: None, + scroll: UniformListScrollHandle::new(), + focus, + note: None, + _poll: poll, + _subscriptions: subscriptions, + } + } + + /// Lines read from the files. Shown at once unless paused; counted on Resume if they are. + fn take(&mut self, read: Vec<(Source, Vec)>, cx: &mut Context) { + if read.is_empty() { + return; + } + for (source, lines) in read { + self.tail.push(source, lines); + } + if self.paused_at.is_none() { + self.refresh(cx); + } else { + cx.notify(); + } + } + + /// Draws the filter over the tail again, and follows the end unless paused. + fn refresh(&mut self, cx: &mut Context) { + self.visible = self.tail.visible(&self.filter); + self.longest = self.visible.iter().enumerate().max_by_key(|(_, line)| line.text.len()).map_or(0, |(ix, _)| ix); + if self.paused_at.is_none() { + self.scroll.scroll_to_bottom(); + } + cx.notify(); + } + + fn set_paused(&mut self, paused: bool, cx: &mut Context) { + self.paused_at = paused.then(|| self.tail.seq()); + self.refresh(cx); + } + + fn dismiss(&mut self, window: &mut Window, cx: &mut Context) { + if !self.filter.text.is_empty() { + self.search.update(cx, |input, cx| input.set_text("", cx)); + self.filter.text.clear(); + self.refresh(cx); + return; + } + window.remove_window(); + } + + fn noted(&mut self, words: String, cx: &mut Context) { + self.note = Some((Instant::now(), words)); + cx.notify(); + cx.spawn(async move |this, cx| { + cx.background_executor().timer(NOTE).await; + let _ = this.update(cx, |_, cx| cx.notify()); + }) + .detach(); + } + + fn copy_visible(&mut self, cx: &mut Context) { + let text = log_tail::copy_text(&self.visible, self.filter.source.is_none()); + let count = self.visible.len(); + cx.write_to_clipboard(ClipboardItem::new_string(text)); + self.noted(format!("Copied {count} {}", if count == 1 { "line" } else { "lines" }), cx); + } + + fn save(&mut self, cx: &mut Context) { + cx.spawn(async move |this, cx| { + let paths = cx.background_executor().spawn(async { save_bundles() }).await; + let _ = this.update(cx, |this, cx| this.noted(format!("Saved to {}", saved_note(&paths)), cx)); + }) + .detach(); + } + + /// Stores Verbose logging in chatd, which moves its own ceiling and a call's at once; this + /// process moves when the answer is in. + fn set_verbose(&mut self, on: bool, cx: &mut Context) { + let value = verbose_value(on); + let request = Request::Set { scope: GLOBAL.to_owned(), key: LOG_LEVEL.to_owned(), value: value.clone() }; + cx.spawn(async move |this, cx| { + let answer = cx.background_executor().spawn(async move { crate::client::ask(&request) }).await; + let _ = this.update(cx, |this, cx| { + if !matches!(answer, Ok(Response::Ok)) { + this.noted("Verbose logging could not be changed: chatd is not running.".to_owned(), cx); + return; + } + let mut values = prefs::values(); + values.set(GLOBAL, LOG_LEVEL, value); + if let Some(guard) = protocol::log_policy::current() { + guard.apply(LogPolicy::for_settings(&values)); + } + prefs::set_values(values); + cx.notify(); + }); + }) + .detach(); + } + + fn rows(&mut self, range: Range, _: &mut Window, _: &mut Context) -> Vec { + let every = self.filter.source.is_none(); + range + .filter_map(|ix| self.visible.get(ix)) + .map(|line| { + let color = match line.level { + Some(Level::Error) => theme::danger(), + Some(Level::Warn) => theme::warning(), + Some(Level::Debug | Level::Trace) => theme::text_faint(), + Some(Level::Info) | None => theme::text(), + }; + div() + .h(px(ROW)) + .px(px(16.)) + .flex() + .items_center() + .whitespace_nowrap() + .font_family(theme::MONO) + .text_size(theme::sized(12.)) + .line_height(px(ROW)) + .when(every, |row| row.child(div().flex_none().w(px(SOURCE_COLUMN)).text_color(theme::text_faint()).child(line.source.name()))) + .child(div().flex_none().text_color(color).child(SharedString::from(line.text.clone()))) + .into_any_element() + }) + .collect() + } + + fn toolbar(&mut self, window: &mut Window, cx: &mut Context) -> impl IntoElement { + let focused = self.search.focus_handle(cx).is_focused(window); + let field = search_field(focused).w(px(240.)).child(div().flex_1().min_w_0().child(self.search.clone())); + let mut levels = segmented(); + for level in Level::SHOWN { + levels = levels.child(segment(SharedString::from(format!("level-{}", level.name())), level.name(), self.filter.level == level).on_click( + cx.listener(move |this, _, _, cx| { + this.filter.level = level; + this.refresh(cx); + }), + )); + } + let hide_noise = self.filter.hide_noise; + let noise = div() + .id("noise") + .flex() + .items_center() + .gap(px(8.)) + .cursor_pointer() + .child(switch("noise-switch", "Hide noise", hide_noise)) + .child(div().type_ui().text_color(theme::text_soft()).child("Hide noise")) + .on_click(cx.listener(move |this, _, _, cx| { + this.filter.hide_noise = !hide_noise; + this.refresh(cx); + })); + let pause = match self.paused_at { + None => button("pause", ButtonKind::Secondary, "Pause").on_click(cx.listener(|this, _, _, cx| this.set_paused(true, cx))), + Some(at) => { + let waiting = self.tail.seq().saturating_sub(at); + let label = if waiting == 0 { "Resume".to_owned() } else { format!("Resume ({waiting} new)") }; + button("pause", ButtonKind::Primary, label).on_click(cx.listener(|this, _, _, cx| this.set_paused(false, cx))) + } + }; + div() + .flex_none() + .h(px(44.)) + .px(px(16.)) + .flex() + .items_center() + .gap(px(12.)) + .border_b_1() + .border_color(theme::hairline()) + .child(field) + .child(levels) + .child(noise) + .child(div().flex_1()) + .child(pause) + .child(button("copy", ButtonKind::Secondary, "Copy visible").on_click(cx.listener(|this, _, _, cx| this.copy_visible(cx)))) + .child(button("save", ButtonKind::Secondary, "Save debug log").on_click(cx.listener(|this, _, _, cx| this.save(cx)))) + } + + fn strip(&mut self, window: &mut Window, cx: &mut Context) -> impl IntoElement { + let mut sources = segmented().child(segment("source-all", "All", self.filter.source.is_none()).on_click(cx.listener(|this, _, _, cx| { + this.filter.source = None; + this.refresh(cx); + }))); + for source in Source::ALL { + sources = sources.child(segment(SharedString::from(format!("source-{}", source.name())), source.name(), self.filter.source == Some(source)).on_click( + cx.listener(move |this, _, _, cx| { + this.filter.source = Some(source); + this.refresh(cx); + }), + )); + } + // The traffic lights sit at the left on macOS; Windows' buttons are drawn at the right. + let left = if cfg!(target_os = "macos") { 84. } else { 16. }; + super::layout::drags_window(div()) + .h(px(theme::STRIP)) + .flex_none() + .pl(px(left)) + .pr(px(super::chrome::width(window) + 12.)) + .flex() + .items_center() + .gap(px(16.)) + .border_b_1() + .border_color(theme::hairline()) + .child(div().type_title().text_color(theme::text()).child("Logs")) + .child(sources) + } + + fn footer(&mut self, cx: &mut Context) -> impl IntoElement { + let on = verbose(); + let shown = self.visible.len(); + let kept: usize = Source::ALL.iter().map(|source| self.tail.len(*source)).sum(); + div() + .flex_none() + .h(px(40.)) + .px(px(16.)) + .flex() + .items_center() + .gap(px(8.)) + .border_t_1() + .border_color(theme::hairline()) + .bg(theme::sidebar()) + .child( + div() + .id("verbose") + .flex() + .items_center() + .gap(px(8.)) + .cursor_pointer() + .child(switch("verbose-switch", "Verbose logging", on)) + .child(div().type_ui().text_color(theme::text()).child("Verbose logging")) + .on_click(cx.listener(move |this, _, _, cx| this.set_verbose(!on, cx))), + ) + .child(div().type_small().text_color(theme::text_faint()).child(VERBOSE_NOTE)) + .child(div().flex_1()) + .child(div().type_small().text_color(theme::text_faint()).child(format!("{shown} of {kept} lines"))) + .child(button("reveal", ButtonKind::Ghost, crate::host::REVEAL).on_click(cx.listener(|_, _, _, cx| { + cx.reveal_path(&protocol::log_policy::logs_dir()); + }))) + } +} + +impl Focusable for LogsWindow { + fn focus_handle(&self, _: &App) -> FocusHandle { + self.focus.clone() + } +} + +impl Render for LogsWindow { + fn render(&mut self, window: &mut Window, cx: &mut Context) -> impl IntoElement { + let body = if self.visible.is_empty() { + let words = if self.tail.seq() == 0 { "No lines yet. They appear here as they are written." } else { "No lines match the filter." }; + div().flex_1().flex().items_center().justify_center().type_ui().text_color(theme::text_faint()).child(words).into_any_element() + } else { + div() + .flex_1() + .min_h_0() + .py(px(4.)) + .child( + uniform_list("log-lines", self.visible.len(), cx.processor(Self::rows)) + .with_width_from_item(Some(self.longest)) + .with_horizontal_sizing_behavior(ListHorizontalSizingBehavior::Unconstrained) + .track_scroll(&self.scroll) + .size_full(), + ) + .into_any_element() + }; + let note = self.note.as_ref().filter(|(at, _)| at.elapsed() < NOTE).map(|(_, words)| { + div().absolute().bottom(px(56.)).left_0().right_0().flex().justify_center().child( + super::components::toast(Some(("icons/check.svg", theme::text_soft())), words.clone()).w(px(420.)), + ) + }); + let close = super::chrome::buttons(window, |_, window, _| window.remove_window()); + div() + .size_full() + .relative() + .flex() + .flex_col() + .bg(theme::canvas()) + .font_family(theme::FONT) + .text_color(theme::text()) + .key_context("Logs") + .track_focus(&self.focus) + .on_action(cx.listener(|this, _: &Dismiss, window, cx| this.dismiss(window, cx))) + .on_action(cx.listener(|_, _: &super::CloseWindow, window, _| window.remove_window())) + .child(self.strip(window, cx)) + .child(self.toolbar(window, cx)) + .child(body) + .child(self.footer(cx)) + .children(note) + .children(close) + .children(super::chrome::edges(window)) + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn verbose_on_stores_debug_and_off_clears_the_row() { + assert_eq!(verbose_value(true).as_deref(), Some("debug")); + // The test environment sets no TINYCLIENT_LOG_LEVEL. + if std::env::var("TINYCLIENT_LOG_LEVEL").is_err() { + assert_eq!(verbose_value(false), None); + } + assert!(protocol::settings::valid(GLOBAL, LOG_LEVEL, "debug") && protocol::settings::valid(GLOBAL, LOG_LEVEL, "info")); + } +} diff --git a/crates/tinyclient/src/gui/mod.rs b/crates/tinyclient/src/gui/mod.rs index 964fc184..0790c8cb 100644 --- a/crates/tinyclient/src/gui/mod.rs +++ b/crates/tinyclient/src/gui/mod.rs @@ -19,6 +19,7 @@ pub(crate) mod debug_launch; mod hotkeys; mod input; mod layout; +mod logs; mod pane; mod people; mod phone; @@ -54,7 +55,7 @@ gpui::actions!( AttachFile, CloseWindow, SearchConversation, SearchEverywhere, BiggerText, SmallerText, ActualSize, FullScreen, MarkUnread, MarkSpaceRead, ShowDetails, Star, Mute, StartCall, OpenInNetwork, CopyLink, Minimize, Zoom, ShowWindow, KeyboardShortcuts, ReleaseNotes, - CopyDiagnostics, ReportProblem + CopyDiagnostics, ReportProblem, ShowLogs ] ); diff --git a/crates/tinyclient/src/gui/settings/pages.rs b/crates/tinyclient/src/gui/settings/pages.rs index a8ed3a4b..20a27e33 100644 --- a/crates/tinyclient/src/gui/settings/pages.rs +++ b/crates/tinyclient/src/gui/settings/pages.rs @@ -669,11 +669,9 @@ impl SettingsWindow { div() .flex() .gap(px(8.)) - .child( - button("B1-log", ButtonKind::Secondary, "Save debug log") - .w(px(controls::ABOUT_ACTION)) - .on_click(cx.listener(|this, _, _, cx| this.save_debug_log(cx))), - ) + .child(button("B2-view", ButtonKind::Secondary, "View logs").on_click(cx.listener(|_, _, _, cx| crate::gui::logs::open(cx)))) + // Three buttons do not fit at the column's width; the one under Copy keeps it. + .child(button("B1-log", ButtonKind::Secondary, "Save debug log").on_click(cx.listener(|this, _, _, cx| this.save_debug_log(cx)))) .child(button("B2", ButtonKind::Secondary, crate::host::REVEAL).w(px(controls::ABOUT_ACTION)).on_click(cx.listener( |_, _, _, cx| { let logs = protocol::log_policy::logs_dir(); @@ -685,6 +683,12 @@ impl SettingsWindow { }, ))), ), + "B4" => { + let second = Some(crate::gui::logs::VERBOSE_NOTE.to_owned()); + self.switch_row(id, crate::gui::logs::verbose(), false, second, |this, on, cx| { + this.set("B4", GLOBAL.into(), protocol::settings::LOG_LEVEL, crate::gui::logs::verbose_value(on), cx) + }, cx) + } "B3" => row( label, None, @@ -1654,24 +1658,8 @@ impl SettingsWindow { } fn save_debug_log(&mut self, cx: &mut Context) { - self.off_thread(cx, || { - let mut paths = Vec::new(); - if let Some(guard) = protocol::log_policy::current() { - if let Ok(Some(path)) = guard.export_bundle() { - paths.push(path.display().to_string()); - } - } - if let Ok(Response::LogsSaved { paths: more }) = crate::client::ask(&Request::SaveLogs) { - paths.extend(more); - } - paths - }, |this, paths, cx| { - let note = if paths.is_empty() { - "Debug logs are turned off.".to_owned() - } else { - protocol::log_policy::logs_dir().join("bundles").display().to_string() - }; - this.log_note = Some((std::time::Instant::now(), note)); + self.off_thread(cx, crate::gui::logs::save_bundles, |this, paths, cx| { + this.log_note = Some((std::time::Instant::now(), crate::gui::logs::saved_note(&paths))); cx.notify(); cx.spawn(async move |this, cx| { cx.background_executor().timer(std::time::Duration::from_secs(4)).await; @@ -1829,7 +1817,7 @@ impl SettingsWindow { let plate = crate::gui::components::brand_mark(if phone::active() { 80. } else { 96. }); let credit = |words: &'static str| div().px(px(controls::side())).py(px(6.)).type_small().when(phone::active(), |line| line.py(px(12.)).phone_preview()).text_color(theme::text_soft()).child(words); // A phone has no folder to show, nor a debug log to save into one (B2). - let tools = if phone::active() { self.group(&["B1", "B3"], None, window, cx) } else { self.group(&["B1", "B2", "B3"], None, window, cx) }; + let tools = if phone::active() { self.group(&["B1", "B3"], None, window, cx) } else { self.group(&["B1", "B2", "B4", "B3"], None, window, cx) }; div() .flex() .flex_col() diff --git a/crates/tinyclient/src/gui/settings/rows.rs b/crates/tinyclient/src/gui/settings/rows.rs index 5b056d80..58f1899d 100644 --- a/crates/tinyclient/src/gui/settings/rows.rs +++ b/crates/tinyclient/src/gui/settings/rows.rs @@ -97,6 +97,7 @@ pub const ROWS: &[Row] = &[ row("D3", Storage, "", "Clear saved messages and files", &[], &["clear", "delete", "cache", "free space"]), row("B1", About, "", "Copy diagnostics", &[], &["support", "bug", "report", "version", "log"]), row("B2", About, "", "Logs", &[], &["log", "debug", "support"]), + row("B4", About, "", "Verbose logging", &[], &["log", "debug", "verbose", "trace", "support"]), row("B3", About, "", "Reset all settings", &[], &["reset", "defaults", "factory"]), ]; @@ -269,6 +270,7 @@ pub const SHORTCUTS: &[Shortcut] = &[ key("Conversation", "Open in App", "⌥⌘O"), key("Window", "Minimize", "⌘M"), key("Help", "Keyboard Shortcuts", "⌘/"), + key("Help", "Logs", "⇧⌘L"), key("Calls", "Mute or unmute", "⇧⌘M"), key("Calls", "Deafen or undeafen", "⇧⌘D"), key("Calls", "Leave the call", "⇧⌘H"), @@ -420,7 +422,7 @@ mod tests { assert!(found, "{} is not in {}", shortcut.command, shortcut.menu); } // The menu items bound in `menubar::bind_keys` and `gui::bind_keys`. - for (menu, command) in [("tinyclient", "Settings…"), ("File", "New Message"), ("File", "Close Window"), ("View", "Bigger Text"), ("Help", "Keyboard Shortcuts"), ("Conversation", "Start Call")] { + for (menu, command) in [("tinyclient", "Settings…"), ("File", "New Message"), ("File", "Close Window"), ("View", "Bigger Text"), ("Help", "Keyboard Shortcuts"), ("Help", "Logs"), ("Conversation", "Start Call")] { assert!(SHORTCUTS.iter().any(|s| s.menu == menu && s.command == command), "{command} is missing"); } } diff --git a/crates/tinyclient/src/lib.rs b/crates/tinyclient/src/lib.rs index 34387764..682bce8e 100644 --- a/crates/tinyclient/src/lib.rs +++ b/crates/tinyclient/src/lib.rs @@ -29,6 +29,9 @@ mod gui; #[cfg(all(feature = "gui", any(target_os = "ios", target_os = "android")))] mod host; #[cfg(all(feature = "gui", any(target_os = "ios", target_os = "android")))] +#[allow(dead_code)] +mod log_tail; +#[cfg(all(feature = "gui", any(target_os = "ios", target_os = "android")))] mod lottie; #[cfg(all(feature = "gui", any(target_os = "ios", target_os = "android")))] mod tiny_attach; diff --git a/crates/tinyclient/src/log_tail.rs b/crates/tinyclient/src/log_tail.rs new file mode 100644 index 00000000..042dadc4 --- /dev/null +++ b/crates/tinyclient/src/log_tail.rs @@ -0,0 +1,411 @@ +//! What the Logs window (Help › Logs) shows: the tail of each process's file in +//! `log_policy::logs_dir()`, kept to the last [`KEEP`] lines a process, and the filter over them. +//! +//! The files are what is read, not the in-memory ring: they are what the operator sees on disk and +//! what Save debug log is checked against, and chatd and mediad write theirs without being asked. +//! Every line in them went through `log_policy::render`, so it is already redacted; nothing here +//! adds to a line but the name of the file it came from. +//! +//! Nothing here touches the window, so it is tested without one. + +use std::collections::VecDeque; +use std::fs::File; +use std::io::{self, Read, Seek, SeekFrom}; +use std::path::PathBuf; +use std::sync::Arc; + +/// Lines kept for each process. A line is about 150 bytes, so three full rings are a few MB. +pub const KEEP: usize = 5000; +/// How far back from the end the first read starts: enough for [`KEEP`] lines, and less than +/// the 2 MiB a file rolls at. +const BACKFILL: u64 = 1024 * 1024; +/// A line longer than this with no end yet is shown as it is rather than held. +const PARTIAL_LIMIT: usize = 64 * 1024; + +/// Lines that say nothing about tinyclient: GPUI on Windows logs the first when a window +/// redraws inside another's update, and the second when a monitor sleeps. "Hide noise" drops them. +pub const NOISE: &[&str] = &["RefCell already borrowed", "No monitor detected!"]; + +#[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)] +pub enum Source { + Tinyclient, + Chatd, + Mediad, +} + +impl Source { + pub const ALL: [Source; 3] = [Source::Tinyclient, Source::Chatd, Source::Mediad]; + + pub const fn name(self) -> &'static str { + match self { + Source::Tinyclient => "tinyclient", + Source::Chatd => "chatd", + Source::Mediad => "mediad", + } + } + + fn index(self) -> usize { + self as usize + } + + pub fn path(self) -> PathBuf { + protocol::log_policy::logs_dir().join(format!("{}.log", self.name())) + } +} + +/// Ordered from the fewest lines to the most, so a filter keeps what is at or below it. +#[derive(Clone, Copy, Debug, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub enum Level { + Error, + Warn, + Info, + Debug, + Trace, +} + +impl Level { + /// The choices the window offers. Debug shows trace too. + pub const SHOWN: [Level; 4] = [Level::Error, Level::Warn, Level::Info, Level::Debug]; + + pub const fn name(self) -> &'static str { + match self { + Level::Error => "Error", + Level::Warn => "Warn", + Level::Info => "Info", + Level::Debug => "Debug", + Level::Trace => "Trace", + } + } +} + +/// The level a file line starts with (`render` writes `warn chatd::media ...`). `None` for a +/// line that does not, such as the second line of a message with a newline in it. +pub fn level_of(line: &str) -> Option { + Some(match line.split_once(' ').map_or(line, |(word, _)| word) { + "error" => Level::Error, + "warn" => Level::Warn, + "info" => Level::Info, + "debug" => Level::Debug, + "trace" => Level::Trace, + _ => return None, + }) +} + +pub fn is_noise(text: &str) -> bool { + NOISE.iter().any(|noise| text.contains(noise)) +} + +/// One line of a file. `seq` orders lines across the three files in the order they were read. +#[derive(Debug, PartialEq, Eq)] +pub struct Line { + pub source: Source, + pub level: Option, + pub seq: u64, + pub text: String, +} + +/// Splits what was read into whole lines. A line with no end yet waits in `partial` for the next +/// read, unless it has grown past [`PARTIAL_LIMIT`]. Bytes are kept until the line ends, so a +/// character cut by the read is whole when it is decoded. +pub fn split_lines(partial: &mut Vec, chunk: &[u8]) -> Vec { + partial.extend_from_slice(chunk); + let mut lines = Vec::new(); + let mut start = 0; + while let Some(end) = partial[start..].iter().position(|byte| *byte == b'\n') { + let line = &partial[start..start + end]; + let line = line.strip_suffix(b"\r").unwrap_or(line); + lines.push(String::from_utf8_lossy(line).into_owned()); + start += end + 1; + } + partial.drain(..start); + if partial.len() > PARTIAL_LIMIT { + lines.push(String::from_utf8_lossy(partial).into_owned()); + partial.clear(); + } + lines +} + +/// Where one file has been read to. +#[derive(Debug)] +pub struct Follow { + path: PathBuf, + /// `None` until the first read, which starts near the end. + offset: Option, + partial: Vec, +} + +impl Follow { + pub fn new(path: PathBuf) -> Follow { + Follow { path, offset: None, partial: Vec::new() } + } + + /// The whole lines written since the last read. The first read takes the last + /// [`BACKFILL`] bytes and drops the line it starts inside. A file shorter than where the last + /// read ended was rolled (`log_policy::rotate_log`): the new one is read from its start. A + /// file that is not there yet reads as nothing. + pub fn read(&mut self) -> io::Result> { + let mut file = match File::open(&self.path) { + Ok(file) => file, + Err(err) if err.kind() == io::ErrorKind::NotFound => return Ok(Vec::new()), + Err(err) => return Err(err), + }; + let len = file.metadata()?.len(); + let (from, mid_line) = match self.offset { + None => (len.saturating_sub(BACKFILL), len > BACKFILL), + Some(offset) if offset > len => { + self.partial.clear(); + (0, false) + } + Some(offset) => (offset, false), + }; + if from == len { + self.offset = Some(len); + return Ok(Vec::new()); + } + file.seek(SeekFrom::Start(from))?; + let mut chunk = Vec::with_capacity((len - from) as usize); + file.take(len - from).read_to_end(&mut chunk)?; + self.offset = Some(from + chunk.len() as u64); + let mut lines = split_lines(&mut self.partial, &chunk); + if mid_line && !lines.is_empty() { + lines.remove(0); + } + Ok(lines) + } +} + +/// The last [`KEEP`] lines of each file, and the next sequence number. +#[derive(Debug)] +pub struct Tail { + rings: [VecDeque>; 3], + keep: usize, + seq: u64, +} + +impl Default for Tail { + fn default() -> Self { + Tail::with_keep(KEEP) + } +} + +impl Tail { + pub fn with_keep(keep: usize) -> Tail { + Tail { rings: Default::default(), keep, seq: 0 } + } + + /// Adds lines read from `source`'s file. A line with no level of its own continues the one + /// before it and takes its level, so a level filter keeps a message's lines together. + pub fn push(&mut self, source: Source, lines: Vec) { + let ring = &mut self.rings[source.index()]; + let mut level = ring.back().and_then(|line| line.level); + for text in lines { + level = level_of(&text).or(level); + self.seq += 1; + ring.push_back(Arc::new(Line { source, level, seq: self.seq, text })); + if ring.len() > self.keep { + ring.pop_front(); + } + } + } + + /// Lines read so far, kept or not: the window counts what arrived while it was paused. + pub fn seq(&self) -> u64 { + self.seq + } + + pub fn len(&self, source: Source) -> usize { + self.rings[source.index()].len() + } + + /// The lines `filter` keeps, oldest first. With every source, the three files interleave + /// in the order their lines were read. + pub fn visible(&self, filter: &Filter) -> Vec> { + let mut out: Vec> = match filter.source { + Some(source) => self.rings[source.index()].iter().filter(|line| filter.admits(line)).cloned().collect(), + None => self.rings.iter().flatten().filter(|line| filter.admits(line)).cloned().collect(), + }; + if filter.source.is_none() { + out.sort_by_key(|line| line.seq); + } + out + } +} + +/// What the window shows of the tail. +#[derive(Clone, Debug, PartialEq, Eq)] +pub struct Filter { + /// `None` is every process. + pub source: Option, + /// The most detailed level shown; Debug includes trace. + pub level: Level, + /// Shown only if the line holds these words, in any case. Empty keeps everything. + pub text: String, + pub hide_noise: bool, +} + +impl Default for Filter { + fn default() -> Self { + Filter { source: None, level: Level::Debug, text: String::new(), hide_noise: true } + } +} + +impl Filter { + pub fn admits(&self, line: &Line) -> bool { + if self.source.is_some_and(|source| source != line.source) { + return false; + } + let ceiling = if self.level == Level::Debug { Level::Trace } else { self.level }; + if line.level.is_some_and(|level| level > ceiling) { + return false; + } + if self.hide_noise && is_noise(&line.text) { + return false; + } + let words = self.text.trim(); + words.is_empty() || contains_folded(&line.text, words) + } +} + +/// Whether `haystack` holds `needle`, ignoring ASCII case. Log lines are mostly ASCII, and this +/// allocates nothing per line. +fn contains_folded(haystack: &str, needle: &str) -> bool { + let (haystack, needle) = (haystack.as_bytes(), needle.as_bytes()); + needle.len() <= haystack.len() && haystack.windows(needle.len()).any(|window| window.eq_ignore_ascii_case(needle)) +} + +/// The lines as Copy visible puts them on the clipboard: with every source shown, each line +/// says which file it came from. +pub fn copy_text(lines: &[Arc], every_source: bool) -> String { + let mut out = String::new(); + for line in lines { + if every_source { + out.push_str(line.source.name()); + out.push_str(": "); + } + out.push_str(&line.text); + out.push('\n'); + } + out +} + +#[cfg(test)] +mod tests { + use super::*; + use std::io::Write; + + fn texts(lines: &[Arc]) -> Vec<&str> { + lines.iter().map(|line| line.text.as_str()).collect() + } + + fn scratch(name: &str) -> PathBuf { + let dir = std::env::temp_dir().join(format!("tinyclient-log-tail-{}-{name}", std::process::id())); + let _ = std::fs::remove_dir_all(&dir); + std::fs::create_dir_all(&dir).unwrap(); + dir.join("chatd.log") + } + + #[test] + fn levels_are_read_from_the_first_word() { + assert_eq!(level_of("warn chatd::media call state session=ab"), Some(Level::Warn)); + assert_eq!(level_of("error log RefCell already borrowed"), Some(Level::Error)); + assert_eq!(level_of("trace mediad x"), Some(Level::Trace)); + assert_eq!(level_of("debug"), Some(Level::Debug)); + assert_eq!(level_of(" at line 2 of a message"), None); + assert_eq!(level_of("warning chatd"), None); + assert_eq!(level_of(""), None); + assert!(Level::Error < Level::Warn && Level::Info < Level::Debug && Level::Debug < Level::Trace); + } + + #[test] + fn split_holds_a_line_until_it_ends_and_a_character_until_it_is_whole() { + let mut partial = Vec::new(); + assert_eq!(split_lines(&mut partial, b"info a\r\nwarn b"), ["info a"]); + assert_eq!(partial, b"warn b"); + // "é" is two bytes; the read ends between them. + assert!(split_lines(&mut partial, b" \xc3").is_empty()); + assert_eq!(split_lines(&mut partial, b"\xa9\n\n"), ["warn b é", ""]); + assert!(partial.is_empty()); + let long = vec![b'x'; PARTIAL_LIMIT + 1]; + assert_eq!(split_lines(&mut partial, &long).len(), 1); + assert!(partial.is_empty()); + } + + #[test] + fn the_ring_keeps_the_last_lines_of_each_source_alone() { + let mut tail = Tail::with_keep(3); + tail.push(Source::Chatd, (0..5).map(|n| format!("info chatd {n}")).collect()); + tail.push(Source::Mediad, vec!["warn mediad one".into()]); + assert_eq!(tail.len(Source::Chatd), 3); + assert_eq!(tail.len(Source::Mediad), 1); + assert_eq!(tail.seq(), 6); + let chatd = tail.visible(&Filter { source: Some(Source::Chatd), ..Filter::default() }); + assert_eq!(texts(&chatd), ["info chatd 2", "info chatd 3", "info chatd 4"]); + // Every source: in the order read. + tail.push(Source::Chatd, vec!["info chatd 5".into()]); + let all = tail.visible(&Filter::default()); + assert_eq!(texts(&all), ["info chatd 3", "info chatd 4", "warn mediad one", "info chatd 5"]); + } + + #[test] + fn a_line_without_a_level_takes_the_one_before_it() { + let mut tail = Tail::default(); + tail.push(Source::Tinyclient, vec!["debug tinyclient first".into(), " second line".into()]); + tail.push(Source::Tinyclient, vec![" third line".into(), "warn tinyclient other".into()]); + let info = tail.visible(&Filter { level: Level::Info, ..Filter::default() }); + assert_eq!(texts(&info), ["warn tinyclient other"]); + assert_eq!(tail.visible(&Filter::default()).len(), 4); + } + + #[test] + fn the_filter_takes_source_level_words_and_noise() { + let mut tail = Tail::default(); + tail.push(Source::Tinyclient, vec![ + "error log RefCell already borrowed log.target=gpui::window".into(), + "warn tinyclient No monitor detected!".into(), + "info tinyclient::gui opened Settings".into(), + "debug tinyclient::gui drew 3 rows".into(), + "trace tinyclient::gui deep".into(), + ]); + tail.push(Source::Chatd, vec!["error chatd Discord said 401".into()]); + let shown = |filter: Filter| texts(&tail.visible(&filter)).into_iter().map(str::to_owned).collect::>(); + assert_eq!(shown(Filter::default()).len(), 4); + assert_eq!(shown(Filter { hide_noise: false, ..Filter::default() }).len(), 6); + assert_eq!(shown(Filter { level: Level::Warn, ..Filter::default() }), ["error chatd Discord said 401"]); + assert_eq!(shown(Filter { level: Level::Info, source: Some(Source::Tinyclient), ..Filter::default() }), ["info tinyclient::gui opened Settings"]); + assert_eq!(shown(Filter { text: " DISCORD ".into(), ..Filter::default() }), ["error chatd Discord said 401"]); + assert!(shown(Filter { text: "nothing like this".into(), ..Filter::default() }).is_empty()); + let copied = copy_text(&tail.visible(&Filter { level: Level::Warn, ..Filter::default() }), true); + assert_eq!(copied, "chatd: error chatd Discord said 401\n"); + } + + #[test] + fn follow_backfills_then_reads_appends_and_starts_over_after_a_roll() { + let path = scratch("follow"); + let mut follow = Follow::new(path.clone()); + assert!(follow.read().unwrap().is_empty()); + let mut file = std::fs::OpenOptions::new().create(true).append(true).open(&path).unwrap(); + file.write_all(b"info chatd one\ninfo chatd tw").unwrap(); + assert_eq!(follow.read().unwrap(), ["info chatd one"]); + file.write_all(b"o\nwarn chatd three\n").unwrap(); + assert_eq!(follow.read().unwrap(), ["info chatd two", "warn chatd three"]); + assert!(follow.read().unwrap().is_empty()); + drop(file); + // Rolled: the live file starts again, shorter than where the last read ended. + std::fs::rename(&path, path.with_extension("log.1")).unwrap(); + std::fs::write(&path, b"info chatd new\n").unwrap(); + assert_eq!(follow.read().unwrap(), ["info chatd new"]); + // A first read from the middle of a big file drops the line it lands in. + let big = path.with_file_name("mediad.log"); + let line = "debug mediad::video uplink video=0 estimate=Some(1000000) loss=Some(0.0)\n"; + let mut text = String::new(); + while (text.len() as u64) < BACKFILL + 4096 { + text.push_str(line); + } + text.push_str("info mediad last\n"); + std::fs::write(&big, &text).unwrap(); + let lines = Follow::new(big).read().unwrap(); + assert!(lines.iter().all(|read| format!("{read}\n") == line || read == "info mediad last")); + assert_eq!(lines.last().map(String::as_str), Some("info mediad last")); + let _ = std::fs::remove_dir_all(path.parent().unwrap()); + } +} diff --git a/crates/tinyclient/src/main.rs b/crates/tinyclient/src/main.rs index cec6447f..96ae8480 100644 --- a/crates/tinyclient/src/main.rs +++ b/crates/tinyclient/src/main.rs @@ -12,6 +12,10 @@ mod update; mod frames; #[cfg(any(feature = "gui", test))] mod tiny_attach; +// The Logs window's model; without a window, only its tests use it. +#[cfg(any(feature = "gui", test))] +#[cfg_attr(not(feature = "gui"), allow(dead_code))] +mod log_tail; // The window draws what it says; without one, only its tests use it. #[cfg(any(feature = "gui", test))] #[cfg_attr(not(feature = "gui"), allow(dead_code))] diff --git a/docs/logging.md b/docs/logging.md index 006a576c..c39d3a2c 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -14,6 +14,8 @@ Environment, read at process start: The same three are settings `log_level`, `log_ring`, and `log_export`. A stored row replaces that one environment value after chatd opens its database, and again in the window when settings load. A missing row leaves the environment value. Garbage reads as the default. The subscriber admits our own crates up to `trace` from the start, and the render ceiling is what drops events, so raising the level takes effect for events after that change. `reqwest`, `hyper`, `h2`, `sqlx`, `tower`, and `str0m` stay at `warn` in the subscriber. +Verbose logging (Settings › About, and the Logs window) stores `log_level` as `debug`, and clears it when turned off (or stores `info` when `TINYCLIENT_LOG_LEVEL` alone would keep debug). chatd moves its own ceiling when the row is stored, and sends a running call's or microphone test's mediad `MediaRequest::LogLevel`; the window moves when its settings load again. A mediad or login helper started later gets the ceiling in `TINYCLIENT_LOG_LEVEL` beside `TINYCLIENT_SESSION`. Nothing needs a restart, and the row is kept for the next start. + `TINYCLIENT_SESSION` is 32 hex characters shared by the window, chatd, and mediad. The window adopts chatd's id from `Status.session` when that field is set. ## Files @@ -33,6 +35,8 @@ The old `chatd.log` at the top of the support directory is not opened, copied, o Save debug log in Settings › About writes the window ring and asks chatd, which also asks a live mediad. Export off writes nothing and the window says "Debug logs are turned off." Bundles older than 24 hours are removed on the next save. On Unix the log directory is mode `0700`, and the operator files and the bundle are mode `0600`. +The Logs window (Help › Logs, ⇧⌘L / Ctrl+Shift+L, or View logs in Settings › About) reads `tinyclient.log`, `chatd.log`, and `mediad.log` while it is open, every half second, and keeps the last 5000 lines of each in memory. It filters by process, level, and words, and its Hide noise switch (on by default) drops GPUI's "RefCell already borrowed" and "No monitor detected!" lines. Copy visible puts the lines it shows on the clipboard. It shows only what the files already hold, so nothing it shows has skipped the redaction below. + Stderr gets the same operator line when it is a terminal or `JOURNAL_STREAM` is set. chatd's stderr is otherwise discarded. ## What is kept out diff --git a/docs/product/09-settings.md b/docs/product/09-settings.md index 1ad73ec2..a69b9fbf 100644 --- a/docs/product/09-settings.md +++ b/docs/product/09-settings.md @@ -271,7 +271,8 @@ The tag line should name Discord, Slack, Telegram, Teams, Signal, Messages, and | # | Control | What it does | | --- | --- | --- | | B1 | Copy diagnostics | Version, OS, service state, and account connection states. No message text, names, tokens, or log lines. Save debug log writes the in-memory ring under `logs/bundles/` and shows that directory | -| B2 | Show logs in Finder | Opens `logs/` (`tinyclient.log`, `chatd.log`, `mediad.log`, `login.log`, and `bundles/`) | +| B2 | Show logs in Finder | View logs opens the Logs window (`docs/logging.md`). Show in Finder opens `logs/` (`tinyclient.log`, `chatd.log`, `mediad.log`, `login.log`, and `bundles/`) | +| B4 | Verbose logging | Stores `log_level` `debug`. tinyclient, chatd and a running call's mediad log debug lines at once, and after a restart | | B3 | Reset all settings… | Confirm: "Reset every setting to its default? Accounts, messages and files are not touched." Deletes every row in `settings` with global or account scope and the settings lines in `shell.prefs`. Per-conversation sounds go too | ### Count From d33cc9ddd90977b1b1a28724b291e055837cd8d7 Mon Sep 17 00:00:00 2001 From: Justin Scroggins Date: Tue, 3 Nov 2026 09:47:19 -0500 Subject: [PATCH 2/2] Fetch the rail picture only once the link is up, and let a pause land a little later. Windows CI downloaded the seeded avatar while Discord was still offline, then the READY avatar after connect, so the own-picture test saw two fetches. macOS CI paused a one-second file at 602 ms, two milliseconds outside the old 600 ms window. --- crates/chatd/src/blobs.rs | 21 +++++++++++++++------ crates/chatd/tests/playback.rs | 5 ++++- 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/crates/chatd/src/blobs.rs b/crates/chatd/src/blobs.rs index 435edb24..09ff903d 100644 --- a/crates/chatd/src/blobs.rs +++ b/crates/chatd/src/blobs.rs @@ -9,8 +9,8 @@ //! shell sends for what is on screen; nothing is fetched ahead. //! - A picture asked for as a row's (its avatar, while the row is in `Watching.rows`) waits, //! unfetched, once the row has scrolled away, and goes back in line when it is on screen again. -//! - Each account's own picture (the rail's) is fetched when the account is signed in or starts, -//! and again on each connect if it is not on disk, without the shell asking. +//! - Each account's own picture (the rail's) is fetched once the link is up, and again on each +//! connect if it is not on disk, without the shell asking. Not while the link is still down. //! - A picker's previews (stickers, GIF stills: ids made with [`pick`]) go to //! `media//pick//`, are fetched only while the picker asks for them, and are //! deleted when it closes ([`Blobs::picker_closed`], or [`PICK_IDLE`] without a request). @@ -623,10 +623,11 @@ impl Cache { generation <= closed && !queue.picked.contains_key(account) } - /// Fetches each account's own picture (the rail's) when the account signs in or starts, - /// and on each connect if it is not on disk. Looks at the links every [`OWN_EVERY`] (one - /// lock); the store only while an account that just started or connected has not had its - /// picture asked for, for at most [`OWN_FOR`], since the adapter records us a little after. + /// Fetches each account's own picture (the rail's) once the link is up, and on each connect + /// if it is not on disk. Not while the link is still down: the adapter records who we are as + /// it connects and can replace the id the store already had. Looks at the links every + /// [`OWN_EVERY`] (one lock); the store only while an account that just connected has not had + /// its picture asked for, for at most [`OWN_FOR`], since the adapter records us a little after. fn own_pictures(&self) { struct Own { connected: bool, @@ -660,6 +661,14 @@ impl Cache { continue; }; for (account, own) in seen.iter_mut().filter(|(_, own)| own.until.is_some()) { + // Offline, the store can still hold the picture from the last session, or from a + // test that seeded one. The adapter replaces that id as it connects (Discord's + // READY does). Fetching now takes the stale picture, and the connect that follows + // takes the real one: two downloads of "the" picture. Wait until the link is up, + // which is also when that id is the one the rail will show. + if !own.connected { + continue; + } let Some(avatar) = accounts.iter().find(|row| row.key == *account).and_then(|row| row.avatar.clone()) else { continue; }; diff --git a/crates/chatd/tests/playback.rs b/crates/chatd/tests/playback.rs index 4181c90c..780ef1e9 100644 --- a/crates/chatd/tests/playback.rs +++ b/crates/chatd/tests/playback.rs @@ -213,7 +213,10 @@ fn a_pause_lets_the_process_go_and_play_goes_on_from_there() { sleep(Duration::from_millis(400)); world.ask(PlayRequest::Pause).unwrap(); let paused = world.until_state(PlayState::Paused); - assert!((250..=600).contains(&paused.at), "paused at {}", paused.at); + // 400 ms asleep, plus where mediad already was, plus a little scheduler slack. 600 was two + // milliseconds short on a loaded macOS runner (paused at 602). Still well before the end of + // the one-second file. + assert!((250..=750).contains(&paused.at), "paused at {}", paused.at); until_no_mediad(); let at = world.shown().unwrap().at; assert_eq!(world.shown().unwrap().position(u64::MAX), at, "a paused position does not move");